From patchwork Tue Dec 15 21:45:21 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steve French X-Patchwork-Id: 11975815 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-12.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id E18B4C4361B for ; Tue, 15 Dec 2020 21:46:50 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 9787922CB9 for ; Tue, 15 Dec 2020 21:46:50 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1730231AbgLOVqZ (ORCPT ); Tue, 15 Dec 2020 16:46:25 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:53870 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729816AbgLOVqP (ORCPT ); Tue, 15 Dec 2020 16:46:15 -0500 Received: from mail-lf1-x133.google.com (mail-lf1-x133.google.com [IPv6:2a00:1450:4864:20::133]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 85884C0613D3 for ; Tue, 15 Dec 2020 13:45:34 -0800 (PST) Received: by mail-lf1-x133.google.com with SMTP id m25so43217770lfc.11 for ; Tue, 15 Dec 2020 13:45:34 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:from:date:message-id:subject:to; bh=13bMuXzHIzv+9bEtDU4zCMLMmtIkAQMkAZaQAAJplT0=; b=qvHHIdTjwFtyregf8ENHviuerq+7WCc3yMt+bxCRVaVWzM/2+bbNr0WRJjEpBPMJfz aM2PoylKxcs8rESb3BGQH3mF92y36aWtxrPzHfP81Oez8upZOs+kv1P45m7GEl3R7w/p Zz0dIddVEbnM9t6zvSkf09m+/BDMrIKc5VFT/X9e+qq2f4qQQbPsemi49hqBoLBQBgsI IxwS73pQAqjQ9PgpDNRXxNV9aj2LXTWTfDC/DxM1+e4i7Uiry1OhmS6g3CA0OzS3QefK A3+6SZWnAbqF670m1/0gd0vJpitWN0Gjjur26g06jgRpH5jh+7NrWxA+Eu9Sf1Wou+dB iA/A== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:mime-version:from:date:message-id:subject:to; bh=13bMuXzHIzv+9bEtDU4zCMLMmtIkAQMkAZaQAAJplT0=; b=VrYlmgxMWS/YmeLzGEX0BoofjUMSt2lY1akXa6VviaHO5z7Xz3I+kjVJ0/rAV32dq9 cfuJZ2DoWmXLchYahNqvnw06dQFdp9KHnLWBe/5OlQShuUeNNgNUgddxBigrH5lKoXdn yW7BWRfTUtK6OvA2qLLHVuxBmiJXdLi9RJDD+pxs28Tg4Ta2/PpQUqAp3MMjQJx8Revf Vel1n0rhT53ONJlMwKF7c7nRF8wVdzX0b2WfviDrQfyECoW3IOwO4vF+ty2PPcFCpbkL 0boEVnpv8HQZjG+psMJg9sbG8AsAm6kgJY0M1ybrmUf/mXdv8sX6P8cyu00EWFd3CTBZ dj0Q== X-Gm-Message-State: AOAM531ehcEwZezy9vjYpfOGZ2SFAGP+PuHlMZwgwXWDbanTBWlzDTsw WVrQL8gDJcsn+aNw1yOG3SPfEWe+8olbJixiqEjakbd4iCA= X-Google-Smtp-Source: ABdhPJz/u1Dib4x80OSM3vaXoR7vK40u1WxEWN0vThqWvgEIsh/cwNKJivCRHp0uFH8aPEoqwkQR2gFHjFvhYUE6+sI= X-Received: by 2002:a2e:6a14:: with SMTP id f20mr140878ljc.6.1608068732735; Tue, 15 Dec 2020 13:45:32 -0800 (PST) MIME-Version: 1.0 From: Steve French Date: Tue, 15 Dec 2020 15:45:21 -0600 Message-ID: Subject: [PATCH][SMB3] add additional tracepoints for logging credit changes To: CIFS , Shyam Prasad N Precedence: bulk List-ID: X-Mailing-List: linux-cifs@vger.kernel.org Shyam, I made minor changes to your patch to avoid two places where scredits could be uninitialized From b16acf6a27d386d4611a89d56831426c9c9e4f13 Mon Sep 17 00:00:00 2001 From: Shyam Prasad N Date: Thu, 12 Nov 2020 08:56:49 -0800 Subject: [PATCH 5/5] 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 Signed-off-by: Steve French --- fs/cifs/connect.c | 8 ++++++++ fs/cifs/smb2ops.c | 41 +++++++++++++++++++++++++++++++++++++---- fs/cifs/trace.h | 4 ++++ fs/cifs/transport.c | 15 +++++++++++++++ 4 files changed, 64 insertions(+), 4 deletions(-) diff --git a/fs/cifs/connect.c b/fs/cifs/connect.c index 64a41b32fbb1..5004d5cde795 100644 --- 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 a505cc3e58da..949cd1177147 100644 --- 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 90e0fab69bb8..c3d1a584f251 100644 --- 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/screditsfs/cifs/transport.c b/fs/cifs/transport.c index 36b2ece43403..b4c77bcb61c1 100644 --- 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; } } -- 2.27.0