Aurélien Aptel
2019-Feb-14 20:13 UTC
[Samba] 32 seconds vs 72 minutes -- expected performance difference?
Saurabh Nanda <saurabhnanda at gmail.com> writes:> I found something interesting in /proc/fs/cifs/Stats. Notice the > "QueryDirectories > Failed" number. This keeps increasing as along as `ls > -lR` is running.That's interesting indeed. The verbose logs and network trace would tell us more. -- Aurélien Aptel / SUSE Labs Samba Team GPG: 1839 CB5F 9F5B FB9B AA97 8C99 03C8 A49B 521B D5D3 SUSE Linux GmbH, Maxfeldstraße 5, 90409 Nürnberg, Germany GF: Felix Imendörffer, Jane Smithard, Graham Norton, HRB 21284 (AG Nürnberg)
Saurabh Nanda
2019-Feb-15 04:55 UTC
[Samba] 32 seconds vs 72 minutes -- expected performance difference?
> > That's interesting indeed. The verbose logs and network trace would tell > us more. >I've enabled verbose/debug logging on the client side. Here are a few operations from the log, and my observations on them: 1) Why is the log saying `SMB2` everywhere? Shouldn't it be saying `SMB3`? 2) Is this normal -- fs/cifs/smb2misc.c: Calculated size 157 length 156 mismatch mid 11907 3) Is this normal -- fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release 4) Is this normal -- fs/cifs/readdir.c: index not in buffer - could not findnext into it fs/cifs/readdir.c: could not find entry 5) This definitely seems like some error, right? -- fs/cifs/smb2maperror.c: Mapping SMB2 status code 0x80000006 to POSIX err -61 There is also another data point which _might_ be relevant. It _seems_ that "systemd-resolved" is randomly crashing on the server , possibly because of the mounted samba share. Caveat: I am not completely sure about the correlation between samba mount and systemd-resolved crashes. Nevertheless, I had already asked this question on StackExchange at https://askubuntu.com/questions/1117842/systemd-resolved-crashing-with-failed-to-set-up-mount-namespacing-invalid-argu if you feel that this might be relevant. Further, I can confirm that systemd-resolved had NOT crashed when the following logs were obtained: ## OPERATION 1 - `ls debug.log` -- simply listing a single file. Does anything seem wrong with this? Feb 15 05:41:09 prod-backoffice kernel: [57077.470310] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: CIFS VFS: in cifs_revalidate_dentry_attr as Xid: 1225875 with uid: 0 Feb 15 05:41:09 prod-backoffice kernel: [57077.480006] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/dir.c: name: \debug.log Feb 15 05:41:09 prod-backoffice kernel: [57077.482879] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/dir.c: name: \shared\debug.log Feb 15 05:41:09 prod-backoffice kernel: [57077.485886] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: Update attributes: \shared\debug.log inode 0x00000000e2b41764 count 1 dentry: 0x00000000b5a5453d d_time 0 jiffies 4309162152 Feb 15 05:41:09 prod-backoffice kernel: [57077.492014] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: Getting info on \shared\debug.log Feb 15 05:41:09 prod-backoffice kernel: [57077.495222] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: create/open Feb 15 05:41:09 prod-backoffice kernel: [57077.498168] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=160 Feb 15 05:41:09 prod-backoffice kernel: [57077.503002] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x98 Feb 15 05:41:09 prod-backoffice kernel: [57077.509849] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x9c, smb_buf_length: 0x98 Feb 15 05:41:09 prod-backoffice kernel: [57077.517609] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 0 offset 0 Feb 15 05:41:09 prod-backoffice kernel: [57077.521076] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 157 Feb 15 05:41:09 prod-backoffice kernel: [57077.523925] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: Calculated size 157 length 156 mismatch mid 11907 Feb 15 05:41:09 prod-backoffice kernel: [57077.532680] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=11907 state=4 Feb 15 05:41:09 prod-backoffice kernel: [57077.539926] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:41:09 prod-backoffice kernel: [57077.555133] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Query Info Feb 15 05:41:09 prod-backoffice kernel: [57077.557869] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=104 Feb 15 05:41:09 prod-backoffice kernel: [57077.561909] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0xce Feb 15 05:41:09 prod-backoffice kernel: [57077.565180] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0xd2, smb_buf_length: 0xce Feb 15 05:41:09 prod-backoffice kernel: [57077.569866] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 134 offset 72 Feb 15 05:41:09 prod-backoffice kernel: [57077.573175] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 210 Feb 15 05:41:09 prod-backoffice kernel: [57077.576102] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=11908 state=4 Feb 15 05:41:09 prod-backoffice kernel: [57077.587089] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:41:09 prod-backoffice kernel: [57077.596379] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Close Feb 15 05:41:09 prod-backoffice kernel: [57077.601123] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=88 Feb 15 05:41:09 prod-backoffice kernel: [57077.607675] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x7c Feb 15 05:41:09 prod-backoffice kernel: [57077.611135] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x80, smb_buf_length: 0x7c Feb 15 05:41:09 prod-backoffice kernel: [57077.616214] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 128 Feb 15 05:41:09 prod-backoffice kernel: [57077.619415] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=11909 state=4 Feb 15 05:41:09 prod-backoffice kernel: [57077.630005] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:41:09 prod-backoffice kernel: [57077.634944] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28312117 Feb 15 05:41:09 prod-backoffice kernel: [57077.642045] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28312117 is unchanged Feb 15 05:41:09 prod-backoffice kernel: [57077.649148] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate_dentry_attr (xid = 1225875) rc = 0 ## OPERATION 2 - simply doing an `ls` inside the shared folder Feb 15 05:43:23 prod-backoffice kernel: [57211.288413] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: CIFS VFS: in cifs_revalidate_dentry_attr as Xid: 1225876 with uid: 0 Feb 15 05:43:23 prod-backoffice kernel: [57211.297805] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/dir.c: name: \shared Feb 15 05:43:23 prod-backoffice kernel: [57211.300601] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: Update attributes: \shared inode 0x00000000d46b4cf6 count 1 dentry: 0x000000008b3ec727 d_time 0 jiffies 4309195606 Feb 15 05:43:23 prod-backoffice kernel: [57211.306420] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: Getting info on \shared Feb 15 05:43:23 prod-backoffice kernel: [57211.309217] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: create/open Feb 15 05:43:23 prod-backoffice kernel: [57211.311751] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=136 Feb 15 05:43:23 prod-backoffice kernel: [57211.316616] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x98 Feb 15 05:43:23 prod-backoffice kernel: [57211.319472] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x9c, smb_buf_length: 0x98 Feb 15 05:43:23 prod-backoffice kernel: [57211.328888] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 0 offset 0 Feb 15 05:43:23 prod-backoffice kernel: [57211.335264] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 157 Feb 15 05:43:23 prod-backoffice kernel: [57211.338625] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: Calculated size 157 length 156 mismatch mid 11911 Feb 15 05:43:23 prod-backoffice kernel: [57211.343033] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=11911 state=4 Feb 15 05:43:23 prod-backoffice kernel: [57211.351904] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:43:23 prod-backoffice kernel: [57211.360139] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Query Info Feb 15 05:43:23 prod-backoffice kernel: [57211.364502] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=104 Feb 15 05:43:23 prod-backoffice kernel: [57211.369145] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0xba Feb 15 05:43:23 prod-backoffice kernel: [57211.383446] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0xbe, smb_buf_length: 0xba Feb 15 05:43:23 prod-backoffice kernel: [57211.387866] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 114 offset 72 Feb 15 05:43:23 prod-backoffice kernel: [57211.391061] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 190 Feb 15 05:43:23 prod-backoffice kernel: [57211.393886] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=16 mid=11912 state=4 Feb 15 05:43:23 prod-backoffice kernel: [57211.404390] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:43:23 prod-backoffice kernel: [57211.409698] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Close Feb 15 05:43:23 prod-backoffice kernel: [57211.412316] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=88 Feb 15 05:43:23 prod-backoffice kernel: [57211.416484] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x7c Feb 15 05:43:23 prod-backoffice kernel: [57211.422736] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x80, smb_buf_length: 0x7c Feb 15 05:43:23 prod-backoffice kernel: [57211.430215] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 128 Feb 15 05:43:23 prod-backoffice kernel: [57211.436281] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=11913 state=4 Feb 15 05:43:23 prod-backoffice kernel: [57211.442040] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:43:23 prod-backoffice kernel: [57211.447597] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311556 Feb 15 05:43:23 prod-backoffice kernel: [57211.452408] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311556 is unchanged Feb 15 05:43:23 prod-backoffice kernel: [57211.456927] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: CIFS VFS: leaving cifs_revalidate_dentry_attr (xid = 1225876) rc = 0 Feb 15 05:43:23 prod-backoffice kernel: [57211.461923] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: in cifs_readdir as Xid: 1225877 with uid: 0 Feb 15 05:43:23 prod-backoffice kernel: [57211.466774] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/dir.c: name: \shared Feb 15 05:43:23 prod-backoffice kernel: [57211.470104] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: Full path: \shared start at: 0 Feb 15 05:43:23 prod-backoffice kernel: [57211.473558] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: create/open Feb 15 05:43:23 prod-backoffice kernel: [57211.477060] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=136 Feb 15 05:43:23 prod-backoffice kernel: [57211.482229] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x98 Feb 15 05:43:23 prod-backoffice kernel: [57211.485712] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x9c, smb_buf_length: 0x98 Feb 15 05:43:23 prod-backoffice kernel: [57211.491765] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 0 offset 0 Feb 15 05:43:23 prod-backoffice kernel: [57211.496945] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 157 Feb 15 05:43:23 prod-backoffice kernel: [57211.500748] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: Calculated size 157 length 156 mismatch mid 11914 Feb 15 05:43:23 prod-backoffice kernel: [57211.507074] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=5 mid=11914 state=4 Feb 15 05:43:23 prod-backoffice kernel: [57211.511940] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:43:23 prod-backoffice kernel: [57211.516526] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=98 Feb 15 05:43:23 prod-backoffice kernel: [57211.527271] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x3fee Feb 15 05:43:23 prod-backoffice kernel: [57211.532421] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x3ff2, smb_buf_length: 0x3fee Feb 15 05:43:23 prod-backoffice kernel: [57211.540419] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 16294 offset 72 Feb 15 05:43:23 prod-backoffice kernel: [57211.544908] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 16370 Feb 15 05:43:23 prod-backoffice kernel: [57211.548458] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=14 mid=11915 state=4 Feb 15 05:43:23 prod-backoffice kernel: [57211.554266] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: num entries 185 last_index 185 srch start 00000000d950f9ad srch end 00000000df0e5967 Feb 15 05:43:23 prod-backoffice kernel: [57211.567057] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: initiate cifs search rc 0 Feb 15 05:43:23 prod-backoffice kernel: [57211.570155] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 16294 offset 72 Feb 15 05:43:23 prod-backoffice kernel: [57211.573359] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 16370 Feb 15 05:43:23 prod-backoffice kernel: [57211.576186] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: found entry - pos_in_buf 2 Feb 15 05:43:23 prod-backoffice kernel: [57211.579197] nxt_dir_entry: 204 callbacks suppressed Feb 15 05:43:23 prod-backoffice kernel: [57211.579199] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 00000000516fe645 old entry 00000000d950f9ad Feb 15 05:43:23 prod-backoffice kernel: [57211.585845] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 0000000028598c07 old entry 00000000516fe645 Feb 15 05:43:23 prod-backoffice kernel: [57211.590400] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: entry 2 found Feb 15 05:43:23 prod-backoffice kernel: [57211.593266] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: loop through 183 times filling dir for net buf 00000000f0cba935 Feb 15 05:43:23 prod-backoffice kernel: [57211.598147] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 16294 offset 72 Feb 15 05:43:23 prod-backoffice kernel: [57211.601375] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 16370 Feb 15 05:43:23 prod-backoffice kernel: [57211.635502] cifs_prime_dcache: 202 callbacks suppressed Feb 15 05:43:23 prod-backoffice kernel: [57211.635505] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 18 Feb 15 05:43:23 prod-backoffice kernel: [57211.644419] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311647 Feb 15 05:43:23 prod-backoffice kernel: [57211.650168] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311647 is unchanged Feb 15 05:43:23 prod-backoffice kernel: [57211.654738] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 000000009c67154c old entry 0000000028598c07 Feb 15 05:43:23 prod-backoffice kernel: [57211.659927] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 112 Feb 15 05:43:23 prod-backoffice kernel: [57211.663820] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311573 Feb 15 05:43:23 prod-backoffice kernel: [57211.669089] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311573 is unchanged Feb 15 05:43:23 prod-backoffice kernel: [57211.673779] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 00000000f8c0468b old entry 000000009c67154c Feb 15 05:43:23 prod-backoffice kernel: [57211.683699] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 74 Feb 15 05:43:23 prod-backoffice kernel: [57211.688907] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311738 Feb 15 05:43:23 prod-backoffice kernel: [57211.699163] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311738 is unchanged Feb 15 05:43:23 prod-backoffice kernel: [57211.705335] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 0000000044e0c02e old entry 00000000f8c0468b Feb 15 05:43:23 prod-backoffice kernel: [57211.710947] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 155 Feb 15 05:43:24 prod-backoffice kernel: [57211.714337] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311620 Feb 15 05:43:24 prod-backoffice kernel: [57211.723098] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311620 is unchanged Feb 15 05:43:24 prod-backoffice kernel: [57211.730138] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 00000000261c31b0 old entry 0000000044e0c02e Feb 15 05:43:24 prod-backoffice kernel: [57211.734976] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 174 Feb 15 05:43:24 prod-backoffice kernel: [57211.742004] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311641 Feb 15 05:43:24 prod-backoffice kernel: [57211.749771] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311641 is unchanged Feb 15 05:43:24 prod-backoffice kernel: [57211.754639] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 000000006b3838cc old entry 00000000261c31b0 Feb 15 05:43:24 prod-backoffice kernel: [57211.763357] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 32 Feb 15 05:43:24 prod-backoffice kernel: [57211.769511] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311692 Feb 15 05:43:24 prod-backoffice kernel: [57211.774395] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311692 is unchanged Feb 15 05:43:24 prod-backoffice kernel: [57211.779390] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 0000000014b0235a old entry 000000006b3838cc Feb 15 05:43:24 prod-backoffice kernel: [57211.784052] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 6 Feb 15 05:43:24 prod-backoffice kernel: [57211.787065] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311722 Feb 15 05:43:24 prod-backoffice kernel: [57211.791776] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311722 is unchanged Feb 15 05:43:24 prod-backoffice kernel: [57211.796712] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 00000000cc9d3525 old entry 0000000014b0235a Feb 15 05:43:24 prod-backoffice kernel: [57211.801628] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 194 Feb 15 05:43:24 prod-backoffice kernel: [57211.804798] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311663 Feb 15 05:43:24 prod-backoffice kernel: [57211.809816] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311663 is unchanged Feb 15 05:43:24 prod-backoffice kernel: [57211.814890] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry 00000000c1190073 old entry 00000000cc9d3525 Feb 15 05:43:24 prod-backoffice kernel: [57211.819976] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 127 Feb 15 05:43:24 prod-backoffice kernel: [57211.827505] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: revalidating inode 28311589 Feb 15 05:43:24 prod-backoffice kernel: [57211.832344] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: inode 28311589 is unchanged Feb 15 05:43:24 prod-backoffice kernel: [57211.837162] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for 184 Feb 15 05:43:24 prod-backoffice kernel: [57211.840910] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: last entry in buf at pos 185 126 Feb 15 05:43:24 prod-backoffice kernel: [57211.844146] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: leaving cifs_readdir (xid = 1225877) rc = 0 Feb 15 05:43:24 prod-backoffice kernel: [57211.849328] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: in cifs_readdir as Xid: 1225878 with uid: 0 Feb 15 05:43:24 prod-backoffice kernel: [57211.854272] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: calling findnext2 Feb 15 05:43:24 prod-backoffice kernel: [57211.857338] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=98 Feb 15 05:43:24 prod-backoffice kernel: [57211.864094] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x98e Feb 15 05:43:24 prod-backoffice kernel: [57211.870738] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x992, smb_buf_length: 0x98e Feb 15 05:43:24 prod-backoffice kernel: [57211.879708] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 2374 offset 72 Feb 15 05:43:24 prod-backoffice kernel: [57211.883051] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 2450 Feb 15 05:43:24 prod-backoffice kernel: [57211.886004] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=14 mid=11916 state=4 Feb 15 05:43:24 prod-backoffice kernel: [57211.894200] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: num entries 27 last_index 212 srch start 00000000977aed16 srch end 00000000a1ee1eb9 Feb 15 05:43:24 prod-backoffice kernel: [57211.902845] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 2374 offset 72 Feb 15 05:43:24 prod-backoffice kernel: [57211.906842] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 2450 Feb 15 05:43:24 prod-backoffice kernel: [57211.912321] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: found entry - pos_in_buf 0 Feb 15 05:43:24 prod-backoffice kernel: [57211.919598] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: entry 185 found Feb 15 05:43:24 prod-backoffice kernel: [57211.922880] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: loop through 27 times filling dir for net buf 000000008f8263f4 Feb 15 05:43:24 prod-backoffice kernel: [57211.929562] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 2374 offset 72 Feb 15 05:43:24 prod-backoffice kernel: [57211.932960] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 2450 Feb 15 05:43:24 prod-backoffice kernel: [57211.936087] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: last entry in buf at pos 212 206 Feb 15 05:43:24 prod-backoffice kernel: [57211.939320] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: leaving cifs_readdir (xid = 1225878) rc = 0 Feb 15 05:43:24 prod-backoffice kernel: [57211.948474] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: in cifs_readdir as Xid: 1225879 with uid: 0 Feb 15 05:43:24 prod-backoffice kernel: [57211.953556] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: calling findnext2 Feb 15 05:43:24 prod-backoffice kernel: [57211.956430] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=98 Feb 15 05:43:24 prod-backoffice kernel: [57211.960445] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x49 Feb 15 05:43:24 prod-backoffice kernel: [57211.963336] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x4d, smb_buf_length: 0x49 Feb 15 05:43:24 prod-backoffice kernel: [57211.967691] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 0 offset 0 Feb 15 05:43:24 prod-backoffice kernel: [57211.970758] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=14 mid=11917 state=4 Feb 15 05:43:24 prod-backoffice kernel: [57211.980912] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2maperror.c: Mapping SMB2 status code 0x80000006 to POSIX err -61 Feb 15 05:43:24 prod-backoffice kernel: [57211.987650] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:43:24 prod-backoffice kernel: [57211.992187] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: index not in buffer - could not findnext into it Feb 15 05:43:24 prod-backoffice kernel: [57211.996660] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: could not find entry Feb 15 05:43:24 prod-backoffice kernel: [57211.999584] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: leaving cifs_readdir (xid = 1225879) rc = 0 Feb 15 05:43:24 prod-backoffice kernel: [57212.004091] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: Closedir inode 0x00000000d46b4cf6 Feb 15 05:43:24 prod-backoffice kernel: [57212.007135] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: CIFS VFS: in cifs_closedir as Xid: 1225880 with uid: 0 Feb 15 05:43:24 prod-backoffice kernel: [57212.011469] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: Freeing private data in close dir Feb 15 05:43:24 prod-backoffice kernel: [57212.014398] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Close Feb 15 05:43:24 prod-backoffice kernel: [57212.016906] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: smb_len=88 Feb 15 05:43:24 prod-backoffice kernel: [57212.021014] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x7c Feb 15 05:43:24 prod-backoffice kernel: [57212.026140] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message length: 0x80, smb_buf_length: 0x7c Feb 15 05:43:24 prod-backoffice kernel: [57212.032637] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: cmd=6 mid=11918 state=4 Feb 15 05:43:24 prod-backoffice kernel: [57212.042211] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to cifs_small_buf_release Feb 15 05:43:24 prod-backoffice kernel: [57212.048895] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: Closing uncompleted readdir with rc 0 Feb 15 05:43:24 prod-backoffice kernel: [57212.053324] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: closedir free smb buf in srch struct Feb 15 05:43:24 prod-backoffice kernel: [57212.056786] /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: CIFS VFS: leaving cifs_closedir (xid = 1225880) rc = 0
Rob Townley
2019-Feb-15 06:12 UTC
[Samba] 32 seconds vs 72 minutes -- expected performance difference?
Is plain `ls` fast? Are you using root on the server and some other user on the client? I dont think it applies to your situation, but had a very similar situation years ago. `ls` ... very fast `ls -la` ... very very very slow The filesystem was connected to MS Active Directory (maybe via likewise) and was doing the permissions lookup for user,group,other rwxrwxtwx for each of the groups the current user was a member of by querying AD each time. On Thu, Feb 14, 2019 at 10:56 PM Saurabh Nanda via samba < samba at lists.samba.org> wrote:> > > > That's interesting indeed. The verbose logs and network trace would tell > > us more. > > > > I've enabled verbose/debug logging on the client side. Here are a few > operations from the log, and my observations on them: > > 1) Why is the log saying `SMB2` everywhere? Shouldn't it be saying `SMB3`? > 2) Is this normal -- fs/cifs/smb2misc.c: Calculated size 157 length 156 > mismatch mid 11907 > 3) Is this normal -- fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > 4) Is this normal -- > fs/cifs/readdir.c: index not in buffer - could not findnext into > it > fs/cifs/readdir.c: could not find entry > 5) This definitely seems like some error, right? -- fs/cifs/smb2maperror.c: > Mapping SMB2 status code 0x80000006 to POSIX err -61 > > There is also another data point which _might_ be relevant. It _seems_ that > "systemd-resolved" is randomly crashing on the server , possibly because of > the mounted samba share. Caveat: I am not completely sure about the > correlation between samba mount and systemd-resolved crashes. Nevertheless, > I had already asked this question on StackExchange at > > https://askubuntu.com/questions/1117842/systemd-resolved-crashing-with-failed-to-set-up-mount-namespacing-invalid-argu > if you feel that this might be relevant. Further, I can confirm that > systemd-resolved had NOT crashed when the following logs were obtained: > > ## OPERATION 1 - `ls debug.log` -- simply listing a single file. Does > anything seem wrong with this? > > Feb 15 05:41:09 prod-backoffice kernel: [57077.470310] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: CIFS VFS: in > cifs_revalidate_dentry_attr as Xid: 1225875 with uid: 0 > Feb 15 05:41:09 prod-backoffice kernel: [57077.480006] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/dir.c: name: \debug.log > Feb 15 05:41:09 prod-backoffice kernel: [57077.482879] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/dir.c: name: \shared\debug.log > Feb 15 05:41:09 prod-backoffice kernel: [57077.485886] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: Update attributes: > \shared\debug.log inode 0x00000000e2b41764 count 1 dentry: > 0x00000000b5a5453d d_time 0 jiffies 4309162152 > Feb 15 05:41:09 prod-backoffice kernel: [57077.492014] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: Getting info on > \shared\debug.log > Feb 15 05:41:09 prod-backoffice kernel: [57077.495222] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: create/open > Feb 15 05:41:09 prod-backoffice kernel: [57077.498168] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=160 > Feb 15 05:41:09 prod-backoffice kernel: [57077.503002] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x98 > Feb 15 05:41:09 prod-backoffice kernel: [57077.509849] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x9c, smb_buf_length: 0x98 > Feb 15 05:41:09 prod-backoffice kernel: [57077.517609] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 0 > offset 0 > Feb 15 05:41:09 prod-backoffice kernel: [57077.521076] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 157 > Feb 15 05:41:09 prod-backoffice kernel: [57077.523925] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: Calculated size 157 > length 156 mismatch mid 11907 > Feb 15 05:41:09 prod-backoffice kernel: [57077.532680] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=5 mid=11907 state=4 > Feb 15 05:41:09 prod-backoffice kernel: [57077.539926] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:41:09 prod-backoffice kernel: [57077.555133] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Query Info > Feb 15 05:41:09 prod-backoffice kernel: [57077.557869] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=104 > Feb 15 05:41:09 prod-backoffice kernel: [57077.561909] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0xce > Feb 15 05:41:09 prod-backoffice kernel: [57077.565180] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0xd2, smb_buf_length: 0xce > Feb 15 05:41:09 prod-backoffice kernel: [57077.569866] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 134 > offset 72 > Feb 15 05:41:09 prod-backoffice kernel: [57077.573175] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 210 > Feb 15 05:41:09 prod-backoffice kernel: [57077.576102] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=16 mid=11908 state=4 > Feb 15 05:41:09 prod-backoffice kernel: [57077.587089] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:41:09 prod-backoffice kernel: [57077.596379] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Close > Feb 15 05:41:09 prod-backoffice kernel: [57077.601123] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=88 > Feb 15 05:41:09 prod-backoffice kernel: [57077.607675] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x7c > Feb 15 05:41:09 prod-backoffice kernel: [57077.611135] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x80, smb_buf_length: 0x7c > Feb 15 05:41:09 prod-backoffice kernel: [57077.616214] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 128 > Feb 15 05:41:09 prod-backoffice kernel: [57077.619415] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=6 mid=11909 state=4 > Feb 15 05:41:09 prod-backoffice kernel: [57077.630005] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:41:09 prod-backoffice kernel: [57077.634944] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28312117 > Feb 15 05:41:09 prod-backoffice kernel: [57077.642045] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28312117 is unchanged > Feb 15 05:41:09 prod-backoffice kernel: [57077.649148] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: CIFS VFS: leaving > cifs_revalidate_dentry_attr (xid = 1225875) rc = 0 > > ## OPERATION 2 - simply doing an `ls` inside the shared folder > > Feb 15 05:43:23 prod-backoffice kernel: [57211.288413] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: CIFS VFS: in > cifs_revalidate_dentry_attr as Xid: 1225876 with uid: 0 > Feb 15 05:43:23 prod-backoffice kernel: [57211.297805] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/dir.c: name: \shared > Feb 15 05:43:23 prod-backoffice kernel: [57211.300601] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: Update attributes: > \shared inode 0x00000000d46b4cf6 count 1 dentry: 0x000000008b3ec727 d_time > 0 jiffies 4309195606 > Feb 15 05:43:23 prod-backoffice kernel: [57211.306420] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: Getting info on \shared > Feb 15 05:43:23 prod-backoffice kernel: [57211.309217] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: create/open > Feb 15 05:43:23 prod-backoffice kernel: [57211.311751] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=136 > Feb 15 05:43:23 prod-backoffice kernel: [57211.316616] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x98 > Feb 15 05:43:23 prod-backoffice kernel: [57211.319472] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x9c, smb_buf_length: 0x98 > Feb 15 05:43:23 prod-backoffice kernel: [57211.328888] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 0 > offset 0 > Feb 15 05:43:23 prod-backoffice kernel: [57211.335264] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 157 > Feb 15 05:43:23 prod-backoffice kernel: [57211.338625] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: Calculated size 157 > length 156 mismatch mid 11911 > Feb 15 05:43:23 prod-backoffice kernel: [57211.343033] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=5 mid=11911 state=4 > Feb 15 05:43:23 prod-backoffice kernel: [57211.351904] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:43:23 prod-backoffice kernel: [57211.360139] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Query Info > Feb 15 05:43:23 prod-backoffice kernel: [57211.364502] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=104 > Feb 15 05:43:23 prod-backoffice kernel: [57211.369145] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0xba > Feb 15 05:43:23 prod-backoffice kernel: [57211.383446] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0xbe, smb_buf_length: 0xba > Feb 15 05:43:23 prod-backoffice kernel: [57211.387866] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 114 > offset 72 > Feb 15 05:43:23 prod-backoffice kernel: [57211.391061] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 190 > Feb 15 05:43:23 prod-backoffice kernel: [57211.393886] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=16 mid=11912 state=4 > Feb 15 05:43:23 prod-backoffice kernel: [57211.404390] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:43:23 prod-backoffice kernel: [57211.409698] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Close > Feb 15 05:43:23 prod-backoffice kernel: [57211.412316] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=88 > Feb 15 05:43:23 prod-backoffice kernel: [57211.416484] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x7c > Feb 15 05:43:23 prod-backoffice kernel: [57211.422736] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x80, smb_buf_length: 0x7c > Feb 15 05:43:23 prod-backoffice kernel: [57211.430215] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 128 > Feb 15 05:43:23 prod-backoffice kernel: [57211.436281] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=6 mid=11913 state=4 > Feb 15 05:43:23 prod-backoffice kernel: [57211.442040] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:43:23 prod-backoffice kernel: [57211.447597] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311556 > Feb 15 05:43:23 prod-backoffice kernel: [57211.452408] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311556 is unchanged > Feb 15 05:43:23 prod-backoffice kernel: [57211.456927] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: CIFS VFS: leaving > cifs_revalidate_dentry_attr (xid = 1225876) rc = 0 > Feb 15 05:43:23 prod-backoffice kernel: [57211.461923] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: in > cifs_readdir as Xid: 1225877 with uid: 0 > Feb 15 05:43:23 prod-backoffice kernel: [57211.466774] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/dir.c: name: \shared > Feb 15 05:43:23 prod-backoffice kernel: [57211.470104] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: Full path: \shared > start at: 0 > Feb 15 05:43:23 prod-backoffice kernel: [57211.473558] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: create/open > Feb 15 05:43:23 prod-backoffice kernel: [57211.477060] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=136 > Feb 15 05:43:23 prod-backoffice kernel: [57211.482229] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x98 > Feb 15 05:43:23 prod-backoffice kernel: [57211.485712] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x9c, smb_buf_length: 0x98 > Feb 15 05:43:23 prod-backoffice kernel: [57211.491765] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 0 > offset 0 > Feb 15 05:43:23 prod-backoffice kernel: [57211.496945] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 157 > Feb 15 05:43:23 prod-backoffice kernel: [57211.500748] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: Calculated size 157 > length 156 mismatch mid 11914 > Feb 15 05:43:23 prod-backoffice kernel: [57211.507074] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=5 mid=11914 state=4 > Feb 15 05:43:23 prod-backoffice kernel: [57211.511940] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:43:23 prod-backoffice kernel: [57211.516526] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=98 > Feb 15 05:43:23 prod-backoffice kernel: [57211.527271] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x3fee > Feb 15 05:43:23 prod-backoffice kernel: [57211.532421] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x3ff2, smb_buf_length: 0x3fee > Feb 15 05:43:23 prod-backoffice kernel: [57211.540419] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 16294 > offset 72 > Feb 15 05:43:23 prod-backoffice kernel: [57211.544908] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 16370 > Feb 15 05:43:23 prod-backoffice kernel: [57211.548458] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=14 mid=11915 state=4 > Feb 15 05:43:23 prod-backoffice kernel: [57211.554266] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: num entries 185 > last_index 185 srch start 00000000d950f9ad srch end 00000000df0e5967 > Feb 15 05:43:23 prod-backoffice kernel: [57211.567057] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: initiate cifs search rc > 0 > Feb 15 05:43:23 prod-backoffice kernel: [57211.570155] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 16294 > offset 72 > Feb 15 05:43:23 prod-backoffice kernel: [57211.573359] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 16370 > Feb 15 05:43:23 prod-backoffice kernel: [57211.576186] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: found entry - > pos_in_buf 2 > Feb 15 05:43:23 prod-backoffice kernel: [57211.579197] nxt_dir_entry: 204 > callbacks suppressed > Feb 15 05:43:23 prod-backoffice kernel: [57211.579199] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 00000000516fe645 old entry 00000000d950f9ad > Feb 15 05:43:23 prod-backoffice kernel: [57211.585845] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 0000000028598c07 old entry 00000000516fe645 > Feb 15 05:43:23 prod-backoffice kernel: [57211.590400] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: entry 2 found > Feb 15 05:43:23 prod-backoffice kernel: [57211.593266] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: loop through 183 times > filling dir for net buf 00000000f0cba935 > Feb 15 05:43:23 prod-backoffice kernel: [57211.598147] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 16294 > offset 72 > Feb 15 05:43:23 prod-backoffice kernel: [57211.601375] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 16370 > Feb 15 05:43:23 prod-backoffice kernel: [57211.635502] cifs_prime_dcache: > 202 callbacks suppressed > Feb 15 05:43:23 prod-backoffice kernel: [57211.635505] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 18 > Feb 15 05:43:23 prod-backoffice kernel: [57211.644419] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311647 > Feb 15 05:43:23 prod-backoffice kernel: [57211.650168] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311647 is unchanged > Feb 15 05:43:23 prod-backoffice kernel: [57211.654738] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 000000009c67154c old entry 0000000028598c07 > Feb 15 05:43:23 prod-backoffice kernel: [57211.659927] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 112 > Feb 15 05:43:23 prod-backoffice kernel: [57211.663820] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311573 > Feb 15 05:43:23 prod-backoffice kernel: [57211.669089] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311573 is unchanged > Feb 15 05:43:23 prod-backoffice kernel: [57211.673779] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 00000000f8c0468b old entry 000000009c67154c > Feb 15 05:43:23 prod-backoffice kernel: [57211.683699] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 74 > Feb 15 05:43:23 prod-backoffice kernel: [57211.688907] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311738 > Feb 15 05:43:23 prod-backoffice kernel: [57211.699163] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311738 is unchanged > Feb 15 05:43:23 prod-backoffice kernel: [57211.705335] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 0000000044e0c02e old entry 00000000f8c0468b > Feb 15 05:43:23 prod-backoffice kernel: [57211.710947] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 155 > Feb 15 05:43:24 prod-backoffice kernel: [57211.714337] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311620 > Feb 15 05:43:24 prod-backoffice kernel: [57211.723098] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311620 is unchanged > Feb 15 05:43:24 prod-backoffice kernel: [57211.730138] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 00000000261c31b0 old entry 0000000044e0c02e > Feb 15 05:43:24 prod-backoffice kernel: [57211.734976] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 174 > Feb 15 05:43:24 prod-backoffice kernel: [57211.742004] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311641 > Feb 15 05:43:24 prod-backoffice kernel: [57211.749771] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311641 is unchanged > Feb 15 05:43:24 prod-backoffice kernel: [57211.754639] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 000000006b3838cc old entry 00000000261c31b0 > Feb 15 05:43:24 prod-backoffice kernel: [57211.763357] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 32 > Feb 15 05:43:24 prod-backoffice kernel: [57211.769511] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311692 > Feb 15 05:43:24 prod-backoffice kernel: [57211.774395] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311692 is unchanged > Feb 15 05:43:24 prod-backoffice kernel: [57211.779390] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 0000000014b0235a old entry 000000006b3838cc > Feb 15 05:43:24 prod-backoffice kernel: [57211.784052] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 6 > Feb 15 05:43:24 prod-backoffice kernel: [57211.787065] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311722 > Feb 15 05:43:24 prod-backoffice kernel: [57211.791776] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311722 is unchanged > Feb 15 05:43:24 prod-backoffice kernel: [57211.796712] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 00000000cc9d3525 old entry 0000000014b0235a > Feb 15 05:43:24 prod-backoffice kernel: [57211.801628] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 194 > Feb 15 05:43:24 prod-backoffice kernel: [57211.804798] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311663 > Feb 15 05:43:24 prod-backoffice kernel: [57211.809816] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311663 is unchanged > Feb 15 05:43:24 prod-backoffice kernel: [57211.814890] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: new entry > 00000000c1190073 old entry 00000000cc9d3525 > Feb 15 05:43:24 prod-backoffice kernel: [57211.819976] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 127 > Feb 15 05:43:24 prod-backoffice kernel: [57211.827505] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > revalidating inode 28311589 > Feb 15 05:43:24 prod-backoffice kernel: [57211.832344] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/inode.c: cifs_revalidate_cache: > inode 28311589 is unchanged > Feb 15 05:43:24 prod-backoffice kernel: [57211.837162] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: cifs_prime_dcache: for > 184 > Feb 15 05:43:24 prod-backoffice kernel: [57211.840910] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: last entry in buf at > pos 185 126 > Feb 15 05:43:24 prod-backoffice kernel: [57211.844146] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: leaving > cifs_readdir (xid = 1225877) rc = 0 > Feb 15 05:43:24 prod-backoffice kernel: [57211.849328] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: in > cifs_readdir as Xid: 1225878 with uid: 0 > Feb 15 05:43:24 prod-backoffice kernel: [57211.854272] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: calling findnext2 > Feb 15 05:43:24 prod-backoffice kernel: [57211.857338] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=98 > Feb 15 05:43:24 prod-backoffice kernel: [57211.864094] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x98e > Feb 15 05:43:24 prod-backoffice kernel: [57211.870738] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x992, smb_buf_length: 0x98e > Feb 15 05:43:24 prod-backoffice kernel: [57211.879708] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 2374 > offset 72 > Feb 15 05:43:24 prod-backoffice kernel: [57211.883051] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 2450 > Feb 15 05:43:24 prod-backoffice kernel: [57211.886004] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=14 mid=11916 state=4 > Feb 15 05:43:24 prod-backoffice kernel: [57211.894200] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: num entries 27 > last_index 212 srch start 00000000977aed16 srch end 00000000a1ee1eb9 > Feb 15 05:43:24 prod-backoffice kernel: [57211.902845] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 2374 > offset 72 > Feb 15 05:43:24 prod-backoffice kernel: [57211.906842] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 2450 > Feb 15 05:43:24 prod-backoffice kernel: [57211.912321] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: found entry - > pos_in_buf 0 > Feb 15 05:43:24 prod-backoffice kernel: [57211.919598] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: entry 185 found > Feb 15 05:43:24 prod-backoffice kernel: [57211.922880] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: loop through 27 times > filling dir for net buf 000000008f8263f4 > Feb 15 05:43:24 prod-backoffice kernel: [57211.929562] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 2374 > offset 72 > Feb 15 05:43:24 prod-backoffice kernel: [57211.932960] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 len 2450 > Feb 15 05:43:24 prod-backoffice kernel: [57211.936087] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: last entry in buf at > pos 212 206 > Feb 15 05:43:24 prod-backoffice kernel: [57211.939320] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: leaving > cifs_readdir (xid = 1225878) rc = 0 > Feb 15 05:43:24 prod-backoffice kernel: [57211.948474] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: in > cifs_readdir as Xid: 1225879 with uid: 0 > Feb 15 05:43:24 prod-backoffice kernel: [57211.953556] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: calling findnext2 > Feb 15 05:43:24 prod-backoffice kernel: [57211.956430] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=98 > Feb 15 05:43:24 prod-backoffice kernel: [57211.960445] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x49 > Feb 15 05:43:24 prod-backoffice kernel: [57211.963336] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x4d, smb_buf_length: 0x49 > Feb 15 05:43:24 prod-backoffice kernel: [57211.967691] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: SMB2 data length 0 > offset 0 > Feb 15 05:43:24 prod-backoffice kernel: [57211.970758] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=14 mid=11917 state=4 > Feb 15 05:43:24 prod-backoffice kernel: [57211.980912] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2maperror.c: Mapping SMB2 > status code 0x80000006 to POSIX err -61 > Feb 15 05:43:24 prod-backoffice kernel: [57211.987650] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:43:24 prod-backoffice kernel: [57211.992187] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: index not in buffer - > could not findnext into it > Feb 15 05:43:24 prod-backoffice kernel: [57211.996660] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: could not find entry > Feb 15 05:43:24 prod-backoffice kernel: [57211.999584] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/readdir.c: CIFS VFS: leaving > cifs_readdir (xid = 1225879) rc = 0 > Feb 15 05:43:24 prod-backoffice kernel: [57212.004091] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: Closedir inode > 0x00000000d46b4cf6 > Feb 15 05:43:24 prod-backoffice kernel: [57212.007135] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: CIFS VFS: in cifs_closedir > as Xid: 1225880 with uid: 0 > Feb 15 05:43:24 prod-backoffice kernel: [57212.011469] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: Freeing private data in > close dir > Feb 15 05:43:24 prod-backoffice kernel: [57212.014398] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2pdu.c: Close > Feb 15 05:43:24 prod-backoffice kernel: [57212.016906] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: Sending smb: > smb_len=88 > Feb 15 05:43:24 prod-backoffice kernel: [57212.021014] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/connect.c: RFC1002 header 0x7c > Feb 15 05:43:24 prod-backoffice kernel: [57212.026140] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/smb2misc.c: smb2_check_message > length: 0x80, smb_buf_length: 0x7c > Feb 15 05:43:24 prod-backoffice kernel: [57212.032637] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/transport.c: cifs_sync_mid_result: > cmd=6 mid=11918 state=4 > Feb 15 05:43:24 prod-backoffice kernel: [57212.042211] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_release > Feb 15 05:43:24 prod-backoffice kernel: [57212.048895] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: Closing uncompleted > readdir with rc 0 > Feb 15 05:43:24 prod-backoffice kernel: [57212.053324] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: closedir free smb buf in > srch struct > Feb 15 05:43:24 prod-backoffice kernel: [57212.056786] > /build/linux-Y38gIP/linux-4.15.0/fs/cifs/file.c: CIFS VFS: leaving > cifs_closedir (xid = 1225880) rc = 0 > -- > To unsubscribe from this list go to the following URL and read the > instructions: https://lists.samba.org/mailman/options/samba
Aurélien Aptel
2019-Feb-15 11:05 UTC
[Samba] 32 seconds vs 72 minutes -- expected performance difference?
Saurabh Nanda <saurabhnanda at gmail.com> writes:> 1) Why is the log saying `SMB2` everywhere? Shouldn't it be saying > `SMB3`?"SMB3" is mostly marketing, it inherits almost everything from SMB2 hence why it's often handled by SMB2 code. You will see this in Samba, Wireshark, Linux, and even Microsoft specification "MS-SMB2" which actually covers both versions.> 2) Is this normal -- fs/cifs/smb2misc.c: Calculated size 157 length 156 > mismatch mid 11907Could be a bug or miscalculated length + non critical warning, I also see this on master kernel. Either way I doubt it's slowing everything down.> 3) Is this normal -- fs/cifs/misc.c: Null buffer passed to > cifs_small_buf_releaseThat can be ignored> 4) Is this normal -- > fs/cifs/readdir.c: index not in buffer - could not findnext into > it > fs/cifs/readdir.c: could not find entry > 5) This definitely seems like some error, right? -- fs/cifs/smb2maperror.c: > Mapping SMB2 status code 0x80000006 to POSIX err -610x80000006 is STATUS_NO_MORE_FILES, returned by the server at the end of a listing. Can be ignored, its not added to the stats as it's the expected "error" for the last listing packet.> There is also another data point which _might_ be relevant. It _seems_ that > "systemd-resolved" is randomly crashing on the server , possibly because of > the mounted samba share. Caveat: I am not completely sure about the > correlation between samba mount and systemd-resolved crashes. Nevertheless, > I had already asked this question on StackExchange at > https://askubuntu.com/questions/1117842/systemd-resolved-crashing-with-failed-to-set-up-mount-namespacing-invalid-argu > if you feel that this might be relevant. Further, I can confirm that > systemd-resolved had NOT crashed when the following logs were obtained: > > ## OPERATION 1 - `ls debug.log` -- simply listing a single file. Does > anything seem wrong with this?This is going to be disapointing but we don't see the error that gets added in the stats in this log extract. Have you checked your samba logs as well? There might be useful information in there (might have to increase "log level" in smb.conf, it can go up to 10 but that will generate a *lot* of data). If you still don't want to share the network capture you should at least try to open it yourself in wireshark, it would save everyone time. You can find out the protocol negotiated by filtering for smb2.cmd == 0 And looking at the Response SMB2 > Negotiate Protocol Response > Dialect in the lower panel. Note that if you re-mounted during the capture or if some error happened the kernel might have tried to reconnect automatically and you will see multiple Req/Resp. You can filter for packets with errors like so: smb2 && smb2.nt_status != 0x80000006 && smb2.nt_status != 0 You can ignore "MORE_PROCESSING_REQUIRED" and ioctl error "FS_DRIVER_REQUIRED" as well. They will show up on every reconnection. Also, please attach files or disable word-wrapping when you send logs in the future. Cheers, -- Aurélien Aptel / SUSE Labs Samba Team GPG: 1839 CB5F 9F5B FB9B AA97 8C99 03C8 A49B 521B D5D3 SUSE Linux GmbH, Maxfeldstraße 5, 90409 Nürnberg, Germany GF: Felix Imendörffer, Jane Smithard, Graham Norton, HRB 21284 (AG Nürnberg)
Possibly Parallel Threads
- 32 seconds vs 72 minutes -- expected performance difference?
- 32 seconds vs 72 minutes -- expected performance difference?
- 32 seconds vs 72 minutes -- expected performance difference?
- 32 seconds vs 72 minutes -- expected performance difference?
- 32 seconds vs 72 minutes -- expected performance difference?