@@ -742,6 +742,8 @@ static void cifs_umount_begin(struct super_block *sb)
spin_lock(&cifs_tcp_ses_lock);
spin_lock(&tcon->tc_lock);
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_see_umount);
if ((tcon->tc_count > 1) || (tcon->status == TID_EXITING)) {
/* we have other mounts to same share or we have
already tried to umount this and woken up
@@ -1188,6 +1188,7 @@ struct cifs_fattr {
*/
struct cifs_tcon {
struct list_head tcon_list;
+ int debug_id; /* Debugging for tracing */
int tc_count;
struct list_head rlist; /* reconnect list */
spinlock_t tc_lock; /* protect anything here that is not protected */
@@ -305,7 +305,7 @@ cifs_get_tcp_session(struct smb3_fs_context *ctx,
struct TCP_Server_Info *primary_server);
extern void cifs_put_tcp_session(struct TCP_Server_Info *server,
int from_reconnect);
-extern void cifs_put_tcon(struct cifs_tcon *tcon);
+extern void cifs_put_tcon(struct cifs_tcon *tcon, enum smb3_tcon_ref_trace trace);
extern void cifs_release_automount_timer(void);
@@ -719,8 +719,6 @@ static inline int cifs_create_options(struct cifs_sb_info *cifs_sb, int options)
return options;
}
-struct super_block *cifs_get_tcon_super(struct cifs_tcon *tcon);
-void cifs_put_tcon_super(struct super_block *sb);
int cifs_wait_for_server_reconnect(struct TCP_Server_Info *server, bool retry);
/* Put references of @ses and @ses->dfs_root_ses */
@@ -2434,6 +2434,8 @@ cifs_find_tcon(struct cifs_ses *ses, struct smb3_fs_context *ctx)
continue;
}
++tcon->tc_count;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_get_find);
spin_unlock(&tcon->tc_lock);
spin_unlock(&cifs_tcp_ses_lock);
return tcon;
@@ -2443,7 +2445,7 @@ cifs_find_tcon(struct cifs_ses *ses, struct smb3_fs_context *ctx)
}
void
-cifs_put_tcon(struct cifs_tcon *tcon)
+cifs_put_tcon(struct cifs_tcon *tcon, enum smb3_tcon_ref_trace trace)
{
unsigned int xid;
struct cifs_ses *ses;
@@ -2459,6 +2461,7 @@ cifs_put_tcon(struct cifs_tcon *tcon)
cifs_dbg(FYI, "%s: tc_count=%d\n", __func__, tcon->tc_count);
spin_lock(&cifs_tcp_ses_lock);
spin_lock(&tcon->tc_lock);
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count - 1, trace);
if (--tcon->tc_count > 0) {
spin_unlock(&tcon->tc_lock);
spin_unlock(&cifs_tcp_ses_lock);
@@ -2756,7 +2759,7 @@ cifs_put_tlink(struct tcon_link *tlink)
}
if (!IS_ERR(tlink_tcon(tlink)))
- cifs_put_tcon(tlink_tcon(tlink));
+ cifs_put_tcon(tlink_tcon(tlink), netfs_trace_tcon_ref_put_tlink);
kfree(tlink);
}
@@ -3321,7 +3324,7 @@ void cifs_mount_put_conns(struct cifs_mount_ctx *mnt_ctx)
int rc = 0;
if (mnt_ctx->tcon)
- cifs_put_tcon(mnt_ctx->tcon);
+ cifs_put_tcon(mnt_ctx->tcon, netfs_trace_tcon_ref_put_mnt_ctx);
else if (mnt_ctx->ses)
cifs_put_smb_ses(mnt_ctx->ses);
else if (mnt_ctx->server)
@@ -82,6 +82,11 @@ int cifs_fscache_get_super_cookie(struct cifs_tcon *tcon)
}
pr_err("Cache volume key already in use (%s)\n", key);
vcookie = NULL;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_see_fscache_collision);
+ } else {
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_see_fscache_okay);
}
tcon->fscache = vcookie;
@@ -102,6 +107,8 @@ void cifs_fscache_release_super_cookie(struct cifs_tcon *tcon)
cifs_fscache_fill_volume_coherency(tcon, &cd);
fscache_relinquish_volume(tcon->fscache, &cd, false);
tcon->fscache = NULL;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_see_fscache_relinq);
}
void cifs_fscache_get_inode_cookie(struct inode *inode)
@@ -113,6 +113,7 @@ struct cifs_tcon *
tcon_info_alloc(bool dir_leases_enabled)
{
struct cifs_tcon *ret_buf;
+ static atomic_t tcon_debug_id;
ret_buf = kzalloc(sizeof(*ret_buf), GFP_KERNEL);
if (!ret_buf)
@@ -129,7 +130,8 @@ tcon_info_alloc(bool dir_leases_enabled)
atomic_inc(&tconInfoAllocCount);
ret_buf->status = TID_NEW;
- ++ret_buf->tc_count;
+ ret_buf->debug_id = atomic_inc_return(&tcon_debug_id);
+ ret_buf->tc_count = 1;
spin_lock_init(&ret_buf->tc_lock);
INIT_LIST_HEAD(&ret_buf->openFileList);
INIT_LIST_HEAD(&ret_buf->tcon_list);
@@ -141,6 +143,8 @@ tcon_info_alloc(bool dir_leases_enabled)
#ifdef CONFIG_CIFS_DFS_UPCALL
INIT_LIST_HEAD(&ret_buf->dfs_ses_list);
#endif
+ trace_smb3_tcon_ref(ret_buf->debug_id, ret_buf->tc_count,
+ netfs_trace_tcon_ref_new);
return ret_buf;
}
@@ -152,6 +156,8 @@ tconInfoFree(struct cifs_tcon *tcon)
cifs_dbg(FYI, "Null buffer passed to tconInfoFree\n");
return;
}
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_free);
free_cached_dirs(tcon->cfids);
atomic_dec(&tconInfoAllocCount);
kfree(tcon->nativeFileSystem);
@@ -763,7 +763,7 @@ smb2_cancelled_close_fid(struct work_struct *work)
if (rc)
cifs_tcon_dbg(VFS, "Close cancelled mid failed rc:%d\n", rc);
- cifs_put_tcon(tcon);
+ cifs_put_tcon(tcon, netfs_trace_tcon_ref_put_cancelled_close_fid);
kfree(cancelled);
}
@@ -807,6 +807,8 @@ smb2_handle_cancelled_close(struct cifs_tcon *tcon, __u64 persistent_fid,
if (tcon->tc_count <= 0) {
struct TCP_Server_Info *server = NULL;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_see_cancelled_close);
WARN_ONCE(tcon->tc_count < 0, "tcon refcount is negative");
spin_unlock(&cifs_tcp_ses_lock);
@@ -819,12 +821,14 @@ smb2_handle_cancelled_close(struct cifs_tcon *tcon, __u64 persistent_fid,
return 0;
}
tcon->tc_count++;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_get_cancelled_close);
spin_unlock(&cifs_tcp_ses_lock);
rc = __smb2_handle_cancelled_cmd(tcon, SMB2_CLOSE_HE, 0,
persistent_fid, volatile_fid);
if (rc)
- cifs_put_tcon(tcon);
+ cifs_put_tcon(tcon, netfs_trace_tcon_ref_put_cancelled_close);
return rc;
}
@@ -852,7 +856,7 @@ smb2_handle_cancelled_mid(struct mid_q_entry *mid, struct TCP_Server_Info *serve
rsp->PersistentFileId,
rsp->VolatileFileId);
if (rc)
- cifs_put_tcon(tcon);
+ cifs_put_tcon(tcon, netfs_trace_tcon_ref_put_cancelled_mid);
return rc;
}
@@ -2912,8 +2912,11 @@ smb2_get_dfs_refer(const unsigned int xid, struct cifs_ses *ses,
tcon = list_first_entry_or_null(&ses->tcon_list,
struct cifs_tcon,
tcon_list);
- if (tcon)
+ if (tcon) {
tcon->tc_count++;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_get_dfs_refer);
+ }
spin_unlock(&cifs_tcp_ses_lock);
}
@@ -2977,6 +2980,8 @@ smb2_get_dfs_refer(const unsigned int xid, struct cifs_ses *ses,
/* ipc tcons are not refcounted */
spin_lock(&cifs_tcp_ses_lock);
tcon->tc_count--;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_dec_dfs_refer);
/* tc_count can never go negative */
WARN_ON(tcon->tc_count < 0);
spin_unlock(&cifs_tcp_ses_lock);
@@ -4129,6 +4129,8 @@ void smb2_reconnect_server(struct work_struct *work)
list_for_each_entry(tcon, &ses->tcon_list, tcon_list) {
if (tcon->need_reconnect || tcon->need_reopen_files) {
tcon->tc_count++;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_get_reconnect_server);
list_add_tail(&tcon->rlist, &tmp_list);
tcon_selected = true;
}
@@ -4167,7 +4169,7 @@ void smb2_reconnect_server(struct work_struct *work)
if (tcon->ipc)
cifs_put_smb_ses(tcon->ses);
else
- cifs_put_tcon(tcon);
+ cifs_put_tcon(tcon, netfs_trace_tcon_ref_put_reconnect_server);
}
if (!ses_exist)
@@ -189,6 +189,8 @@ smb2_find_smb_sess_tcon_unlocked(struct cifs_ses *ses, __u32 tid)
if (tcon->tid != tid)
continue;
++tcon->tc_count;
+ trace_smb3_tcon_ref(tcon->debug_id, tcon->tc_count,
+ netfs_trace_tcon_ref_get_find_smb2);
return tcon;
}
@@ -3,6 +3,9 @@
* Copyright (C) 2018, Microsoft Corporation.
*
* Author(s): Steve French <stfrench@microsoft.com>
+ *
+ * Please use this 3-part article as a reference for writing new tracepoints:
+ * https://lwn.net/Articles/379903/
*/
#undef TRACE_SYSTEM
#define TRACE_SYSTEM cifs
@@ -15,9 +18,64 @@
#include <linux/inet.h>
/*
- * Please use this 3-part article as a reference for writing new tracepoints:
- * https://lwn.net/Articles/379903/
+ * Specify enums for tracing information.
+ */
+#define smb3_tcon_ref_traces \
+ EM(netfs_trace_tcon_ref_dec_dfs_refer, "DEC_DfsRf") \
+ EM(netfs_trace_tcon_ref_free, "FREE ") \
+ EM(netfs_trace_tcon_ref_get_cancelled_close, "GET_C_Cls") \
+ EM(netfs_trace_tcon_ref_get_dfs_refer, "GET_DfsRe") \
+ EM(netfs_trace_tcon_ref_get_find, "GET_Find ") \
+ EM(netfs_trace_tcon_ref_get_find_smb2, "GET_Find2") \
+ EM(netfs_trace_tcon_ref_get_reconnect_server, "GET_Recon") \
+ EM(netfs_trace_tcon_ref_new, "NEW ") \
+ EM(netfs_trace_tcon_ref_put_cancelled_close, "PUT_C_Cls") \
+ EM(netfs_trace_tcon_ref_put_cancelled_close_fid,"PUT_C_Fid") \
+ EM(netfs_trace_tcon_ref_put_cancelled_mid, "PUT_C_Mid") \
+ EM(netfs_trace_tcon_ref_put_mnt_ctx, "PUT_MntCx") \
+ EM(netfs_trace_tcon_ref_put_reconnect_server, "PUT_Recon") \
+ EM(netfs_trace_tcon_ref_put_tlink, "PUT_Tlink") \
+ EM(netfs_trace_tcon_ref_see_cancelled_close, "SEE_C_Cls") \
+ EM(netfs_trace_tcon_ref_see_fscache_collision, "SEE_F_CO!") \
+ EM(netfs_trace_tcon_ref_see_fscache_okay, "SEE_F_Ok ") \
+ EM(netfs_trace_tcon_ref_see_fscache_relinq, "SEE_F_Rlq") \
+ E_(netfs_trace_tcon_ref_see_umount, "SEE_Umnt ")
+
+#undef EM
+#undef E_
+
+/*
+ * Define those tracing enums.
+ */
+#ifndef __SMB3_DECLARE_TRACE_ENUMS_ONCE_ONLY
+#define __SMB3_DECLARE_TRACE_ENUMS_ONCE_ONLY
+
+#define EM(a, b) a,
+#define E_(a, b) a
+
+enum smb3_tcon_ref_trace { smb3_tcon_ref_traces } __mode(byte);
+
+#undef EM
+#undef E_
+#endif
+
+/*
+ * Export enum symbols via userspace.
+ */
+#define EM(a, b) TRACE_DEFINE_ENUM(a);
+#define E_(a, b) TRACE_DEFINE_ENUM(a);
+
+smb3_tcon_ref_traces;
+
+#undef EM
+#undef E_
+
+/*
+ * Now redefine the EM() and E_() macros to map the enums to the strings that
+ * will be printed in the output.
*/
+#define EM(a, b) { a, b },
+#define E_(a, b) { a, b }
/* For logging errors in read or write */
DECLARE_EVENT_CLASS(smb3_rw_err_class,
@@ -1231,6 +1289,30 @@ DEFINE_SMB3_CREDIT_EVENT(waitff_credits);
DEFINE_SMB3_CREDIT_EVENT(overflow_credits);
DEFINE_SMB3_CREDIT_EVENT(set_credits);
+
+TRACE_EVENT(smb3_tcon_ref,
+ TP_PROTO(unsigned int tcon_debug_id, int ref,
+ enum smb3_tcon_ref_trace trace),
+ TP_ARGS(tcon_debug_id, ref, trace),
+ TP_STRUCT__entry(
+ __field(unsigned int, tcon )
+ __field(int, ref )
+ __field(enum smb3_tcon_ref_trace, trace )
+ ),
+ TP_fast_assign(
+ __entry->tcon = tcon_debug_id;
+ __entry->ref = ref;
+ __entry->trace = trace;
+ ),
+ TP_printk("TC=%08x %s r=%u",
+ __entry->tcon,
+ __print_symbolic(__entry->trace, smb3_tcon_ref_traces),
+ __entry->ref)
+ );
+
+
+#undef EM
+#undef E_
#endif /* _CIFS_TRACE_H */
#undef TRACE_INCLUDE_PATH
Hi Steve, Shyam, Paulo, I've been looking into the duplicate fscache volume cookie message I see when running the generic/013 xfstest on cifs with a "-o fsc" mount option. It turns out that in this particular case, cifs_mount_get_tcon() finds a tcon it can reuse... and then partially reinitialises it - whilst it is still in use by another mount. This is probably a bad idea because it's resetting/changing various values on the tcon without any locking - whilst it may be being accessed by other filesystem operations. Probably the function should more or less drop straight out if the tcon is already set up - as cifs_get_tcon() (which it calls to get a tcon) does. That said, there is the possibility that the second mount wants different parameters - but I'm not sure how that affects things. I added a tracepoint (see attached patch) that allows the evolution of the tcon refcount to be followed. With: echo 1 > /sys/kernel/debug/tracing/events/fscache/fscache_volume/enable echo 1 > /sys/kernel/debug/tracing/events/cifs/smb3_tcon_ref/enable mount //carina/test /xfstest.test -o user=shares,pass=xxx,fsc mount //carina/test /mnt -o user=shares,pass=xxx,fsc umount /xfstest.test umount /mnt I see: mount.cifs-5744 ... 50.282306: smb3_tcon_ref: TC=00000001 NEW r=1 mount.cifs-5744 ... 50.283215: smb3_tcon_ref: TC=00000002 NEW r=1 mount.cifs-5744 ... 50.286871: fscache_volume: V=00000001 NEW acq u=1 mount.cifs-5744 ... 50.286872: smb3_tcon_ref: TC=00000002 SEE_F_Ok r=1 mount.cifs-5744 ... 50.288346: fscache_volume: V=00000001 GET cook u=2 mount.cifs-5810 ... 344.536761: smb3_tcon_ref: TC=00000002 GET_Find r=2 mount.cifs-5810 ... 344.538981: fscache_volume: V=00000002 NEW acq u=1 mount.cifs-5810 ... 344.538982: fscache_volume: V=00000001 *COLLIDE* u=2 mount.cifs-5810 ... 344.538982: fscache_volume: V=00000002 PUT hcoll u=0 mount.cifs-5810 ... 344.538983: fscache_volume: V=00000002 FREE u=0 mount.cifs-5810 ... 344.544859: smb3_tcon_ref: TC=00000002 SEE_F_CO! r=2 mount.cifs-5810 ... 344.546497: smb3_tcon_ref: TC=00000002 PUT_Tlink r=1 umount-6054 ... 1609.705106: fscache_volume: V=00000001 PUT cook u=1 umount-6054 ... 1609.705237: smb3_tcon_ref: TC=00000002 PUT_Tlink r=0 umount-6054 ... 1609.706098: smb3_tcon_ref: TC=00000002 SEE_F_Rlq r=0 umount-6054 ... 1609.706099: smb3_tcon_ref: TC=00000002 FREE r=0 umount-6054 ... 1609.706101: smb3_tcon_ref: TC=00000001 FREE r=1 in the tracebuffer. tcons get labelled with integer debugging IDs as they are created, which you can see in TC=nnnnnnnn. fscache volume cookies similarly get labelled as V=nnnnnnnn. The "GET_Find" line corresponds to the refcount increment in cifs_find_tcon() where it finds an already live tcon and reuses it. This is then followed by fscache attempting to create a second volume cookie because that's driven from cifs_mount_get_tcon() - and cifs reports this as the "SEE_F_CO!" line. Both tcons that were created are freed, but TC=00000001 does not get a final put, but is rather freed directly with a ref still attached - presumably by design. The simplest fix I can make is to take a mutex around the acquisition of the volume cookie, and check to see if I've tried to get one before. That said, it looks like cifs_mount_get_tcon() may have other problems too and a more general solution may be required. David --- commit 072e0337280fb1f1dcca883ca1e6340eb9be265c Author: David Howells <dhowells@redhat.com> Date: Thu Apr 4 13:51:36 2024 +0100 cifs: Add tracing for the tcon struct refcounting