cifs: Add a tracepoint to track credits involved in R/W requests

Add a tracepoint to track the credit changes and server in_flight value
involved in the lifetime of a R/W request, logging it against the
request/subreq debugging ID.  This requires the debugging IDs to be
recorded in the cifs_credits struct.

The tracepoint can be enabled with:

	echo 1 >/sys/kernel/debug/tracing/events/cifs/smb3_rw_credits/enable

Also add a three-state flag to struct cifs_credits to note if we're
interested in determining when the in_flight contribution ends and, if so,
to track whether we've decremented the contribution yet.

Signed-off-by: David Howells <dhowells@redhat.com>
Reviewed-by: Paulo Alcantara (Red Hat) <pc@manguebit.com>
cc: Jeff Layton <jlayton@kernel.org>
cc: linux-cifs@vger.kernel.org
cc: netfs@lists.linux.dev
cc: linux-fsdevel@vger.kernel.org
Signed-off-by: Steve French <stfrench@microsoft.com>

diff --git a/fs/smb/client/cifsglob.h b/fs/smb/client/cifsglob.h
index a865941724c029b2abf17c817d34711d05bcad36..8e86fec7dcd2ba6f54167600f651439540942045 100644 (file)
--- a/fs/smb/client/cifsglob.h
+++ b/fs/smb/client/cifsglob.h
@@ -290,7 +290,7 @@ struct smb_version_operations {
        int (*check_receive)(struct mid_q_entry *, struct TCP_Server_Info *,
                             bool);
        void (*add_credits)(struct TCP_Server_Info *server,
-                           const struct cifs_credits *credits,
+                           struct cifs_credits *credits,
                            const int optype);
        void (*set_credits)(struct TCP_Server_Info *, const int);
        int * (*get_credits_field)(struct TCP_Server_Info *, const int);
@@ -550,8 +550,8 @@ struct smb_version_operations {
                                size_t *, struct cifs_credits *);
        /* adjust previously taken mtu credits to request size */
        int (*adjust_credits)(struct TCP_Server_Info *server,
-                             struct cifs_credits *credits,
-                             const unsigned int payload_size);
+                             struct cifs_io_subrequest *subreq,
+                             unsigned int /*enum smb3_rw_credits_trace*/ trace);
        /* check if we need to issue closedir */
        bool (*dir_needs_close)(struct cifsFileInfo *);
        long (*fallocate)(struct file *, struct cifs_tcon *, int, loff_t,
@@ -848,6 +848,9 @@ static inline void cifs_server_unlock(struct TCP_Server_Info *server)
 struct cifs_credits {
        unsigned int value;
        unsigned int instance;
+       unsigned int in_flight_check;
+       unsigned int rreq_debug_id;
+       unsigned int rreq_debug_index;
 };
 
 static inline unsigned int
@@ -873,7 +876,7 @@ has_credits(struct TCP_Server_Info *server, int *credits, int num_credits)
 }
 
 static inline void
-add_credits(struct TCP_Server_Info *server, const struct cifs_credits *credits,
+add_credits(struct TCP_Server_Info *server, struct cifs_credits *credits,
            const int optype)
 {
        server->ops->add_credits(server, credits, optype);
@@ -897,11 +900,11 @@ set_credits(struct TCP_Server_Info *server, const int val)
 }
 
 static inline int
-adjust_credits(struct TCP_Server_Info *server, struct cifs_credits *credits,
-              const unsigned int payload_size)
+adjust_credits(struct TCP_Server_Info *server, struct cifs_io_subrequest *subreq,
+              unsigned int /* enum smb3_rw_credits_trace */ trace)
 {
        return server->ops->adjust_credits ?
-               server->ops->adjust_credits(server, credits, payload_size) : 0;
+               server->ops->adjust_credits(server, subreq, trace) : 0;
 }
 
 static inline __le64

diff --git a/fs/smb/client/file.c b/fs/smb/client/file.c
index 72cc265bc471b0755008fabf9be8b60191e68525..f8d6ad88335eaf85b37b2203aed99ffcaf7cd416 100644 (file)
--- a/fs/smb/client/file.c
+++ b/fs/smb/client/file.c
@@ -80,6 +80,16 @@ retry:
                return netfs_prepare_write_failed(subreq);
        }
 
+       wdata->credits.rreq_debug_id = subreq->rreq->debug_id;
+       wdata->credits.rreq_debug_index = subreq->debug_index;
+       wdata->credits.in_flight_check = 1;
+       trace_smb3_rw_credits(wdata->rreq->debug_id,
+                             wdata->subreq.debug_index,
+                             wdata->credits.value,
+                             server->credits, server->in_flight,
+                             wdata->credits.value,
+                             cifs_trace_rw_credits_write_prepare);
+
 #ifdef CONFIG_CIFS_SMB_DIRECT
        if (server->smbd_conn)
                subreq->max_nr_segs = server->smbd_conn->max_frmr_depth;
@@ -101,7 +111,7 @@ static void cifs_issue_write(struct netfs_io_subrequest *subreq)
                goto fail;
        }
 
-       rc = adjust_credits(wdata->server, &wdata->credits, wdata->subreq.len);
+       rc = adjust_credits(wdata->server, wdata, cifs_trace_rw_credits_issue_write_adjust);
        if (rc)
                goto fail;
 
@@ -158,7 +168,18 @@ static bool cifs_clamp_length(struct netfs_io_subrequest *subreq)
                return false;
        }
 
+       rdata->credits.in_flight_check = 1;
+       rdata->credits.rreq_debug_id = rreq->debug_id;
+       rdata->credits.rreq_debug_index = subreq->debug_index;
+
+       trace_smb3_rw_credits(rdata->rreq->debug_id,
+                             rdata->subreq.debug_index,
+                             rdata->credits.value,
+                             server->credits, server->in_flight, 0,
+                             cifs_trace_rw_credits_read_submit);
+
        subreq->len = min_t(size_t, subreq->len, rsize);
+
 #ifdef CONFIG_CIFS_SMB_DIRECT
        if (server->smbd_conn)
                subreq->max_nr_segs = server->smbd_conn->max_frmr_depth;
@@ -289,6 +310,15 @@ static void cifs_free_subrequest(struct netfs_io_subrequest *subreq)
 #endif
        }
 
+       if (rdata->credits.value != 0)
+               trace_smb3_rw_credits(rdata->rreq->debug_id,
+                                     rdata->subreq.debug_index,
+                                     rdata->credits.value,
+                                     rdata->server ? rdata->server->credits : 0,
+                                     rdata->server ? rdata->server->in_flight : 0,
+                                     -rdata->credits.value,
+                                     cifs_trace_rw_credits_free_subreq);
+
        add_credits_and_wake_if(rdata->server, &rdata->credits, 0);
        if (rdata->have_xid)
                free_xid(rdata->xid);

diff --git a/fs/smb/client/smb1ops.c b/fs/smb/client/smb1ops.c
index 212ec6f66ec65b15f50275803bbc38b0153c9645..e1f2feb56f45f6ac10ab50875689638da6b7712e 100644 (file)
--- a/fs/smb/client/smb1ops.c
+++ b/fs/smb/client/smb1ops.c
@@ -108,7 +108,7 @@ cifs_find_mid(struct TCP_Server_Info *server, char *buffer)
 
 static void
 cifs_add_credits(struct TCP_Server_Info *server,
-                const struct cifs_credits *credits, const int optype)
+                struct cifs_credits *credits, const int optype)
 {
        spin_lock(&server->req_lock);
        server->credits += credits->value;

diff --git a/fs/smb/client/smb2ops.c b/fs/smb/client/smb2ops.c
index c8e536540895a2e6378ec16b640752134742d134..7fe59235f09016bd19f13bddb94ff0603cebe8aa 100644 (file)
--- a/fs/smb/client/smb2ops.c
+++ b/fs/smb/client/smb2ops.c
@@ -66,7 +66,7 @@ change_conf(struct TCP_Server_Info *server)
 
 static void
 smb2_add_credits(struct TCP_Server_Info *server,
-                const struct cifs_credits *credits, const int optype)
+                struct cifs_credits *credits, const int optype)
 {
        int *val, rc = -1;
        int scredits, in_flight;
@@ -94,7 +94,21 @@ smb2_add_credits(struct TCP_Server_Info *server,
                                            server->conn_id, server->hostname, *val,
                                            add, server->in_flight);
        }
-       WARN_ON_ONCE(server->in_flight == 0);
+       if (credits->in_flight_check > 1) {
+               pr_warn_once("rreq R=%08x[%x] Credits not in flight\n",
+                            credits->rreq_debug_id, credits->rreq_debug_index);
+       } else {
+               credits->in_flight_check = 2;
+       }
+       if (WARN_ON_ONCE(server->in_flight == 0)) {
+               pr_warn_once("rreq R=%08x[%x] Zero in_flight\n",
+                            credits->rreq_debug_id, credits->rreq_debug_index);
+               trace_smb3_rw_credits(credits->rreq_debug_id,
+                                     credits->rreq_debug_index,
+                                     credits->value,
+                                     server->credits, server->in_flight, 0,
+                                     cifs_trace_rw_credits_zero_in_flight);
+       }
        server->in_flight--;
        if (server->in_flight == 0 &&
           ((optype & CIFS_OP_MASK) != CIFS_NEG_OP) &&
@@ -283,16 +297,23 @@ smb2_wait_mtu_credits(struct TCP_Server_Info *server, size_t size,
 
 static int
 smb2_adjust_credits(struct TCP_Server_Info *server,
-                   struct cifs_credits *credits,
-                   const unsigned int payload_size)
+                   struct cifs_io_subrequest *subreq,
+                   unsigned int /*enum smb3_rw_credits_trace*/ trace)
 {
-       int new_val = DIV_ROUND_UP(payload_size, SMB2_MAX_BUFFER_SIZE);
+       struct cifs_credits *credits = &subreq->credits;
+       int new_val = DIV_ROUND_UP(subreq->subreq.len, SMB2_MAX_BUFFER_SIZE);
        int scredits, in_flight;
 
        if (!credits->value || credits->value == new_val)
                return 0;
 
        if (credits->value < new_val) {
+               trace_smb3_rw_credits(subreq->rreq->debug_id,
+                                     subreq->subreq.debug_index,
+                                     credits->value,
+                                     server->credits, server->in_flight,
+                                     new_val - credits->value,
+                                     cifs_trace_rw_credits_no_adjust_up);
                trace_smb3_too_many_credits(server->CurrentMid,
                                server->conn_id, server->hostname, 0, credits->value - new_val, 0);
                cifs_server_dbg(VFS, "request has less credits (%d) than required (%d)",
@@ -308,6 +329,12 @@ smb2_adjust_credits(struct TCP_Server_Info *server,
                in_flight = server->in_flight;
                spin_unlock(&server->req_lock);
 
+               trace_smb3_rw_credits(subreq->rreq->debug_id,
+                                     subreq->subreq.debug_index,
+                                     credits->value,
+                                     server->credits, server->in_flight,
+                                     new_val - credits->value,
+                                     cifs_trace_rw_credits_old_session);
                trace_smb3_reconnect_detected(server->CurrentMid,
                        server->conn_id, server->hostname, scredits,
                        credits->value - new_val, in_flight);
@@ -316,6 +343,11 @@ smb2_adjust_credits(struct TCP_Server_Info *server,
                return -EAGAIN;
        }
 
+       trace_smb3_rw_credits(subreq->rreq->debug_id,
+                             subreq->subreq.debug_index,
+                             credits->value,
+                             server->credits, server->in_flight,
+                             new_val - credits->value, trace);
        server->credits += credits->value - new_val;
        scredits = server->credits;
        in_flight = server->in_flight;

diff --git a/fs/smb/client/smb2pdu.c b/fs/smb/client/smb2pdu.c
index bb84a89e59059243e9da3faa699f4221fe5b08ec..9fc5b11c0b6ced612f7a458f6075495dffa19b84 100644 (file)
--- a/fs/smb/client/smb2pdu.c
+++ b/fs/smb/client/smb2pdu.c
@@ -4502,8 +4502,15 @@ smb2_readv_callback(struct mid_q_entry *mid)
        struct TCP_Server_Info *server = rdata->server;
        struct smb2_hdr *shdr =
                                (struct smb2_hdr *)rdata->iov[0].iov_base;
-       struct cifs_credits credits = { .value = 0, .instance = 0 };
+       struct cifs_credits credits = {
+               .value = 0,
+               .instance = 0,
+               .rreq_debug_id = rdata->rreq->debug_id,
+               .rreq_debug_index = rdata->subreq.debug_index,
+       };
        struct smb_rqst rqst = { .rq_iov = &rdata->iov[1], .rq_nvec = 1 };
+       unsigned int rreq_debug_id = rdata->rreq->debug_id;
+       unsigned int subreq_debug_index = rdata->subreq.debug_index;
 
        if (rdata->got_bytes) {
                rqst.rq_iter      = rdata->subreq.io_iter;
@@ -4587,10 +4594,16 @@ smb2_readv_callback(struct mid_q_entry *mid)
                if (rdata->subreq.start < rdata->subreq.rreq->i_size)
                        rdata->result = 0;
        }
+       trace_smb3_rw_credits(rreq_debug_id, subreq_debug_index, rdata->credits.value,
+                             server->credits, server->in_flight,
+                             0, cifs_trace_rw_credits_read_response_clear);
        rdata->credits.value = 0;
        INIT_WORK(&rdata->subreq.work, smb2_readv_worker);
        queue_work(cifsiod_wq, &rdata->subreq.work);
        release_mid(mid);
+       trace_smb3_rw_credits(rreq_debug_id, subreq_debug_index, 0,
+                             server->credits, server->in_flight,
+                             credits.value, cifs_trace_rw_credits_read_response_add);
        add_credits(server, &credits, 0);
 }
 
@@ -4647,7 +4660,7 @@ smb2_async_readv(struct cifs_io_subrequest *rdata)
                                min_t(int, server->max_credits -
                                                server->credits, credit_request));
 
-               rc = adjust_credits(server, &rdata->credits, rdata->subreq.len);
+               rc = adjust_credits(server, rdata, cifs_trace_rw_credits_call_readv_adjust);
                if (rc)
                        goto async_readv_out;
 
@@ -4766,7 +4779,14 @@ smb2_writev_callback(struct mid_q_entry *mid)
        struct cifs_tcon *tcon = tlink_tcon(wdata->req->cfile->tlink);
        struct TCP_Server_Info *server = wdata->server;
        struct smb2_write_rsp *rsp = (struct smb2_write_rsp *)mid->resp_buf;
-       struct cifs_credits credits = { .value = 0, .instance = 0 };
+       struct cifs_credits credits = {
+               .value = 0,
+               .instance = 0,
+               .rreq_debug_id = wdata->rreq->debug_id,
+               .rreq_debug_index = wdata->subreq.debug_index,
+       };
+       unsigned int rreq_debug_id = wdata->rreq->debug_id;
+       unsigned int subreq_debug_index = wdata->subreq.debug_index;
        ssize_t result = 0;
        size_t written;
 
@@ -4837,9 +4857,15 @@ smb2_writev_callback(struct mid_q_entry *mid)
                                      tcon->tid, tcon->ses->Suid,
                                      wdata->subreq.start, wdata->subreq.len);
 
+       trace_smb3_rw_credits(rreq_debug_id, subreq_debug_index, wdata->credits.value,
+                             server->credits, server->in_flight,
+                             0, cifs_trace_rw_credits_write_response_clear);
        wdata->credits.value = 0;
        cifs_write_subrequest_terminated(wdata, result ?: written, true);
        release_mid(mid);
+       trace_smb3_rw_credits(rreq_debug_id, subreq_debug_index, 0,
+                             server->credits, server->in_flight,
+                             credits.value, cifs_trace_rw_credits_write_response_add);
        add_credits(server, &credits, 0);
 }
 
@@ -4969,7 +4995,7 @@ smb2_async_writev(struct cifs_io_subrequest *wdata)
                                min_t(int, server->max_credits -
                                                server->credits, credit_request));
 
-               rc = adjust_credits(server, &wdata->credits, io_parms->length);
+               rc = adjust_credits(server, wdata, cifs_trace_rw_credits_call_writev_adjust);
                if (rc)
                        goto async_writev_out;
 
@@ -4994,6 +5020,12 @@ async_writev_out:
        cifs_small_buf_release(req);
 out:
        if (rc) {
+               trace_smb3_rw_credits(wdata->rreq->debug_id,
+                                     wdata->subreq.debug_index,
+                                     wdata->credits.value,
+                                     server->credits, server->in_flight,
+                                     -(int)wdata->credits.value,
+                                     cifs_trace_rw_credits_write_response_clear);
                add_credits_and_wake_if(wdata->server, &wdata->credits, 0);
                cifs_write_subrequest_terminated(wdata, rc, true);
        }

diff --git a/fs/smb/client/trace.h b/fs/smb/client/trace.h
index 36d47ce596317005dc0a5c430490157c34abee25..36d5295c2a6f92f1e26acbd0d2b94226b0c46452 100644 (file)
--- a/fs/smb/client/trace.h
+++ b/fs/smb/client/trace.h
@@ -20,6 +20,22 @@
 /*
  * Specify enums for tracing information.
  */
+#define smb3_rw_credits_traces \
+       EM(cifs_trace_rw_credits_call_readv_adjust,     "rd-call-adj") \
+       EM(cifs_trace_rw_credits_call_writev_adjust,    "wr-call-adj") \
+       EM(cifs_trace_rw_credits_free_subreq,           "free-subreq") \
+       EM(cifs_trace_rw_credits_issue_read_adjust,     "rd-issu-adj") \
+       EM(cifs_trace_rw_credits_issue_write_adjust,    "wr-issu-adj") \
+       EM(cifs_trace_rw_credits_no_adjust_up,          "no-adj-up  ") \
+       EM(cifs_trace_rw_credits_old_session,           "old-session") \
+       EM(cifs_trace_rw_credits_read_response_add,     "rd-resp-add") \
+       EM(cifs_trace_rw_credits_read_response_clear,   "rd-resp-clr") \
+       EM(cifs_trace_rw_credits_read_submit,           "rd-submit  ") \
+       EM(cifs_trace_rw_credits_write_prepare,         "wr-prepare ") \
+       EM(cifs_trace_rw_credits_write_response_add,    "wr-resp-add") \
+       EM(cifs_trace_rw_credits_write_response_clear,  "wr-resp-clr") \
+       E_(cifs_trace_rw_credits_zero_in_flight,        "ZERO-IN-FLT")
+
 #define smb3_tcon_ref_traces                                         \
        EM(netfs_trace_tcon_ref_dec_dfs_refer,          "DEC DfsRef") \
        EM(netfs_trace_tcon_ref_free,                   "FRE       ") \
@@ -59,7 +75,8 @@
 #define EM(a, b) a,
 #define E_(a, b) a
 
-enum smb3_tcon_ref_trace { smb3_tcon_ref_traces } __mode(byte);
+enum smb3_rw_credits_trace     { smb3_rw_credits_traces } __mode(byte);
+enum smb3_tcon_ref_trace       { smb3_tcon_ref_traces } __mode(byte);
 
 #undef EM
 #undef E_
@@ -71,6 +88,7 @@ enum smb3_tcon_ref_trace { smb3_tcon_ref_traces } __mode(byte);
 #define EM(a, b) TRACE_DEFINE_ENUM(a);
 #define E_(a, b) TRACE_DEFINE_ENUM(a);
 
+smb3_rw_credits_traces;
 smb3_tcon_ref_traces;
 
 #undef EM
@@ -1316,6 +1334,41 @@ TRACE_EVENT(smb3_tcon_ref,
                      __entry->ref)
            );
 
+TRACE_EVENT(smb3_rw_credits,
+           TP_PROTO(unsigned int rreq_debug_id,
+                    unsigned int subreq_debug_index,
+                    unsigned int subreq_credits,
+                    unsigned int server_credits,
+                    int server_in_flight,
+                    int credit_change,
+                    enum smb3_rw_credits_trace trace),
+           TP_ARGS(rreq_debug_id, subreq_debug_index, subreq_credits,
+                   server_credits, server_in_flight, credit_change, trace),
+           TP_STRUCT__entry(
+                   __field(unsigned int, rreq_debug_id)
+                   __field(unsigned int, subreq_debug_index)
+                   __field(unsigned int, subreq_credits)
+                   __field(unsigned int, server_credits)
+                   __field(int,          in_flight)
+                   __field(int,          credit_change)
+                   __field(enum smb3_rw_credits_trace, trace)
+                            ),
+           TP_fast_assign(
+                   __entry->rreq_debug_id      = rreq_debug_id;
+                   __entry->subreq_debug_index = subreq_debug_index;
+                   __entry->subreq_credits     = subreq_credits;
+                   __entry->server_credits     = server_credits;
+                   __entry->in_flight          = server_in_flight;
+                   __entry->credit_change      = credit_change;
+                   __entry->trace              = trace;
+                          ),
+           TP_printk("R=%08x[%x] %s cred=%u chg=%d pool=%u ifl=%d",
+                     __entry->rreq_debug_id, __entry->subreq_debug_index,
+                     __print_symbolic(__entry->trace, smb3_rw_credits_traces),
+                     __entry->subreq_credits, __entry->credit_change,
+                     __entry->server_credits, __entry->in_flight)
+           );
+
 
 #undef EM
 #undef E_

diff --git a/fs/smb/client/transport.c b/fs/smb/client/transport.c
index 012b9bd069952cec16bec71f03a594d53016450c..adfe0d05870108ab639f6cf8d5760d6f525146b6 100644 (file)
--- a/fs/smb/client/transport.c
+++ b/fs/smb/client/transport.c
@@ -988,10 +988,10 @@ static void
 cifs_compound_callback(struct mid_q_entry *mid)
 {
        struct TCP_Server_Info *server = mid->server;
-       struct cifs_credits credits;
-
-       credits.value = server->ops->get_credits(mid);
-       credits.instance = server->reconnect_instance;
+       struct cifs_credits credits = {
+               .value = server->ops->get_credits(mid),
+               .instance = server->reconnect_instance,
+       };
 
        add_credits(server, &credits, mid->optype);