cifs: Tracepoints and logs for tracing credit changes.

There is at least one suspected bug in crediting changes in cifs.ko
which has come up a few times in the discussions and in a customer
case.

This change adds tracepoints to the code which modifies the server
credit values in any way. The goal is to be able to track the changes
to the credit values of the session to be able to catch when there is
a crediting bug.

Signed-off-by: Shyam Prasad N <sprasad@microsoft.com>
Signed-off-by: Steve French <stfrench@microsoft.com>

diff --git a/fs/cifs/connect.c b/fs/cifs/connect.c
index 64a41b32fbb1a91d941b96a5bd521bc8bb5a313f..509a41ff56b830688e10967cb04162fe298d3bf8 100644 (file)
--- a/fs/cifs/connect.c
+++ b/fs/cifs/connect.c
@@ -845,6 +845,7 @@ static void
 smb2_add_credits_from_hdr(char *buffer, struct TCP_Server_Info *server)
 {
        struct smb2_sync_hdr *shdr = (struct smb2_sync_hdr *)buffer;
+       int scredits = server->credits;
 
        /*
         * SMB1 does not use credits.
@@ -857,6 +858,13 @@ smb2_add_credits_from_hdr(char *buffer, struct TCP_Server_Info *server)
                server->credits += le16_to_cpu(shdr->CreditRequest);
                spin_unlock(&server->req_lock);
                wake_up(&server->request_q);
+
+               trace_smb3_add_credits(server->CurrentMid,
+                               server->hostname, scredits,
+                               le16_to_cpu(shdr->CreditRequest));
+               cifs_server_dbg(FYI, "%s: added %u credits total=%d\n",
+                               __func__, le16_to_cpu(shdr->CreditRequest),
+                               scredits);
        }
 }
 

diff --git a/fs/cifs/smb2ops.c b/fs/cifs/smb2ops.c
index a505cc3e58dab1859081a0e722361b17ec31880a..949cd1177147f036d5e84ee09c4f32b384ec9298 100644 (file)
--- a/fs/cifs/smb2ops.c
+++ b/fs/cifs/smb2ops.c
@@ -100,9 +100,10 @@ smb2_add_credits(struct TCP_Server_Info *server,
        spin_unlock(&server->req_lock);
        wake_up(&server->request_q);
 
-       if (reconnect_detected)
+       if (reconnect_detected) {
                cifs_dbg(FYI, "trying to put %d credits from the old server instance %d\n",
                         add, instance);
+       }
 
        if (server->tcpStatus == CifsNeedReconnect
            || server->tcpStatus == CifsExiting)
@@ -124,7 +125,7 @@ smb2_add_credits(struct TCP_Server_Info *server,
        default:
                trace_smb3_add_credits(server->CurrentMid,
                        server->hostname, rc, add);
-               cifs_dbg(FYI, "add %u credits total=%d\n", add, rc);
+               cifs_dbg(FYI, "%s: added %u credits total=%d\n", __func__, add, rc);
        }
 }
 
@@ -136,6 +137,11 @@ smb2_set_credits(struct TCP_Server_Info *server, const int val)
        if (val == 1)
                server->reconnect_instance++;
        spin_unlock(&server->req_lock);
+
+       trace_smb3_set_credits(server->CurrentMid,
+                       server->hostname, val, val);
+       cifs_dbg(FYI, "%s: set %u credits\n", __func__, val);
+
        /* don't log while holding the lock */
        if (val == 1)
                cifs_dbg(FYI, "set credits to 1 due to smb2 reconnect\n");
@@ -202,6 +208,7 @@ smb2_wait_mtu_credits(struct TCP_Server_Info *server, unsigned int size,
                                DIV_ROUND_UP(*num, SMB2_MAX_BUFFER_SIZE);
                        credits->instance = server->reconnect_instance;
                        server->credits -= credits->value;
+                       scredits = server->credits;
                        server->in_flight++;
                        if (server->in_flight > server->max_in_flight)
                                server->max_in_flight = server->in_flight;
@@ -209,6 +216,12 @@ smb2_wait_mtu_credits(struct TCP_Server_Info *server, unsigned int size,
                }
        }
        spin_unlock(&server->req_lock);
+
+       trace_smb3_add_credits(server->CurrentMid,
+                       server->hostname, scredits, -(credits->value));
+       cifs_dbg(FYI, "%s: removed %u credits total=%d\n",
+                       __func__, credits->value, scredits);
+
        return rc;
 }
 
@@ -218,13 +231,17 @@ smb2_adjust_credits(struct TCP_Server_Info *server,
                    const unsigned int payload_size)
 {
        int new_val = DIV_ROUND_UP(payload_size, SMB2_MAX_BUFFER_SIZE);
+       int scredits;
 
        if (!credits->value || credits->value == new_val)
                return 0;
 
        if (credits->value < new_val) {
-               WARN_ONCE(1, "request has less credits (%d) than required (%d)",
-                         credits->value, new_val);
+               trace_smb3_too_many_credits(server->CurrentMid,
+                               server->hostname, 0, credits->value - new_val);
+               cifs_server_dbg(VFS, "request has less credits (%d) than required (%d)",
+                               credits->value, new_val);
+
                return -ENOTSUPP;
        }
 
@@ -232,15 +249,24 @@ smb2_adjust_credits(struct TCP_Server_Info *server,
 
        if (server->reconnect_instance != credits->instance) {
                spin_unlock(&server->req_lock);
+               trace_smb3_reconnect_detected(server->CurrentMid,
+                       server->hostname, 0, 0);
                cifs_server_dbg(VFS, "trying to return %d credits to old session\n",
                         credits->value - new_val);
                return -EAGAIN;
        }
 
        server->credits += credits->value - new_val;
+       scredits = server->credits;
        spin_unlock(&server->req_lock);
        wake_up(&server->request_q);
        credits->value = new_val;
+
+       trace_smb3_add_credits(server->CurrentMid,
+                       server->hostname, scredits, credits->value - new_val);
+       cifs_dbg(FYI, "%s: adjust added %u credits total=%d\n",
+                       __func__, credits->value - new_val, scredits);
+
        return 0;
 }
 
@@ -2343,6 +2369,7 @@ static bool
 smb2_is_status_pending(char *buf, struct TCP_Server_Info *server)
 {
        struct smb2_sync_hdr *shdr = (struct smb2_sync_hdr *)buf;
+       int scredits;
 
        if (shdr->Status != STATUS_PENDING)
                return false;
@@ -2350,8 +2377,14 @@ smb2_is_status_pending(char *buf, struct TCP_Server_Info *server)
        if (shdr->CreditRequest) {
                spin_lock(&server->req_lock);
                server->credits += le16_to_cpu(shdr->CreditRequest);
+               scredits = server->credits;
                spin_unlock(&server->req_lock);
                wake_up(&server->request_q);
+
+               trace_smb3_add_credits(server->CurrentMid,
+                               server->hostname, scredits, le16_to_cpu(shdr->CreditRequest));
+               cifs_dbg(FYI, "%s: status pending add %u credits total=%d\n",
+                               __func__, le16_to_cpu(shdr->CreditRequest), scredits);
        }
 
        return true;

diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h
index 90e0fab69bb8c1243802a5177bf169f3f2899e8c..c3d1a584f251e4b584ab26b1784a153d72aa6d0c 100644 (file)
--- a/fs/cifs/trace.h
+++ b/fs/cifs/trace.h
@@ -909,8 +909,12 @@ DEFINE_EVENT(smb3_credit_class, smb3_##name,  \
        TP_ARGS(currmid, hostname, credits, credits_to_add))
 
 DEFINE_SMB3_CREDIT_EVENT(reconnect_with_invalid_credits);
+DEFINE_SMB3_CREDIT_EVENT(reconnect_detected);
 DEFINE_SMB3_CREDIT_EVENT(credit_timeout);
+DEFINE_SMB3_CREDIT_EVENT(insufficient_credits);
+DEFINE_SMB3_CREDIT_EVENT(too_many_credits);
 DEFINE_SMB3_CREDIT_EVENT(add_credits);
+DEFINE_SMB3_CREDIT_EVENT(set_credits);
 
 #endif /* _CIFS_TRACE_H */
 

diff --git a/fs/cifs/transport.c b/fs/cifs/transport.c
index 36b2ece434037ae5d01fa00479d8edf2dc3f4d7c..e9abb41aa89bcc12002c61d777d4c4f728e9ffb8 100644 (file)
--- a/fs/cifs/transport.c
+++ b/fs/cifs/transport.c
@@ -527,6 +527,7 @@ wait_for_free_credits(struct TCP_Server_Info *server, const int num_credits,
        int *credits;
        int optype;
        long int t;
+       int scredits = server->credits;
 
        if (timeout < 0)
                t = MAX_JIFFY_OFFSET;
@@ -624,12 +625,18 @@ wait_for_free_credits(struct TCP_Server_Info *server, const int num_credits,
                        /* update # of requests on the wire to server */
                        if ((flags & CIFS_TIMEOUT_MASK) != CIFS_BLOCKING_OP) {
                                *credits -= num_credits;
+                               scredits = *credits;
                                server->in_flight += num_credits;
                                if (server->in_flight > server->max_in_flight)
                                        server->max_in_flight = server->in_flight;
                                *instance = server->reconnect_instance;
                        }
                        spin_unlock(&server->req_lock);
+
+                       trace_smb3_add_credits(server->CurrentMid,
+                                       server->hostname, scredits, -(num_credits));
+                       cifs_dbg(FYI, "%s: remove %u credits total=%d\n",
+                                       __func__, num_credits, scredits);
                        break;
                }
        }
@@ -649,10 +656,14 @@ wait_for_compound_request(struct TCP_Server_Info *server, int num,
                          const int flags, unsigned int *instance)
 {
        int *credits;
+       int scredits, sin_flight;
 
        credits = server->ops->get_credits_field(server, flags & CIFS_OP_MASK);
 
        spin_lock(&server->req_lock);
+       scredits = *credits;
+       sin_flight = server->in_flight;
+
        if (*credits < num) {
                /*
                 * Return immediately if not too many requests in flight since
@@ -660,6 +671,10 @@ wait_for_compound_request(struct TCP_Server_Info *server, int num,
                 */
                if (server->in_flight < num - *credits) {
                        spin_unlock(&server->req_lock);
+                       trace_smb3_insufficient_credits(server->CurrentMid,
+                                       server->hostname, scredits, sin_flight);
+                       cifs_dbg(FYI, "%s: %d requests in flight, needed %d total=%d\n",
+                                       __func__, sin_flight, num, scredits);
                        return -ENOTSUPP;
                }
        }