From patchwork Tue Sep 18 09:10:39 2018 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steve French X-Patchwork-Id: 10603871 Return-Path: Received: from mail.wl.linuxfoundation.org (pdx-wl-mail.web.codeaurora.org [172.30.200.125]) by pdx-korg-patchwork-2.web.codeaurora.org (Postfix) with ESMTP id 188DD17E1 for ; Tue, 18 Sep 2018 09:10:53 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 02C142A58B for ; Tue, 18 Sep 2018 09:10:53 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id E90B62A58D; Tue, 18 Sep 2018 09:10:52 +0000 (UTC) X-Spam-Checker-Version: SpamAssassin 3.3.1 (2010-03-16) on pdx-wl-mail.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-8.0 required=2.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FROM,MAILING_LIST_MULTI,RCVD_IN_DNSWL_HI autolearn=ham version=3.3.1 Received: from vger.kernel.org (vger.kernel.org [209.132.180.67]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 5787C2A58B for ; Tue, 18 Sep 2018 09:10:52 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1728925AbeIROmc (ORCPT ); Tue, 18 Sep 2018 10:42:32 -0400 Received: from mail-pl1-f194.google.com ([209.85.214.194]:43009 "EHLO mail-pl1-f194.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1726838AbeIROmc (ORCPT ); Tue, 18 Sep 2018 10:42:32 -0400 Received: by mail-pl1-f194.google.com with SMTP id 38-v6so680048plc.10 for ; Tue, 18 Sep 2018 02:10:51 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=mime-version:from:date:message-id:subject:to:cc; bh=iAJKXEulyH2dKW2R22R/cvL1dtQDStRariItXhQ48VY=; b=vRpH+jttplEwAbyvhUPesuXkEKeg/Rd2aX+qPQZ1BMi4e9e8h3bZOuy5FkBF37xO6q LEY75N1wIeS2t1bpgB6VNwRkIMwtix+Ttg0RlotAdFM4txucOB9xv+UB3yEIs7pgr296 yg+Y+FA3YdDdj2IkTRtZ4sow6kztMQtZqKu8fwRHglH/j3LnupS+HKgjFwlSHa5w04C7 pB8Mz14chwjm3/9PP4gCTXuqUJL7t6jxErZEt3CzlnFp1B+eLqcnqrBHRbvoifSuvrrz 0aFGEMGSc2qALVRPp/afVHW/jWa7W2pvxxr2KqtDZW5BasHE+Fx7Cdm8h99kJW0k46XN 542Q== 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:cc; bh=iAJKXEulyH2dKW2R22R/cvL1dtQDStRariItXhQ48VY=; b=gNU1a6CISfZES9sNg5puKZ/8+omOb8pHe0k0yaUYRmDhkkdvEIraUfwkmwfOrdmVbm jPDmdmZnVfAUXmToVaViqkHRKLajTjslHoaice9xwItLMQ5TGbTsdRthS5gR1my2I/4R mrv1cpH9xDqAvj7CGE1T/3LcwRbNmoYfBij/QGSWBP+jfpnRED6kh3PIfSVR+y/G07c5 j/HGLYceutBwW88COb99Iun3+/kQ2MHwLsUajpWjGPxmIXuRwFy1W/XM6fnYGUP2ZJhM OBoERnfTO6Z+uJlxmJF4EPiU32wOa9LvrAY6p4pIjsUpKHuBvggyQn2B2vQwE3TkiFzO 1+VQ== X-Gm-Message-State: APzg51CNsoFVY/KmLmMbVbGyNF/+MZUEbZOx611FFlSFAdOaHvr4uASM xFV0DNVOhua7UFaiolUSL9OGUnQKC1XBKsnNai2Hk/Ax X-Google-Smtp-Source: ANB0VdYq1dWotvkQZNIId5paSK557xqe74dT8KkdywemSozKzfdjU6mrSGLvX8wZtUndjwJYMlt9anq+DaWbLMjVq0k= X-Received: by 2002:a17:902:bd07:: with SMTP id p7-v6mr28048434pls.32.1537261850736; Tue, 18 Sep 2018 02:10:50 -0700 (PDT) MIME-Version: 1.0 From: Steve French Date: Tue, 18 Sep 2018 04:10:39 -0500 Message-ID: Subject: smb3: add way to control slow response threshold for logging and stats To: samba-technical , CIFS Cc: "Stefan (metze) Metzmacher" Sender: linux-cifs-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-cifs@vger.kernel.org X-Virus-Scanned: ClamAV using ClamSMTP (Thanks to Metze for suggestion) /proc/fs/cifs/Stats when CONFIG_CIFS_STATS2 is enabled logs 'slow' responses, but depending on the server you are debugging a one second timeout may be too fast, so allow setting it to a larger number of seconds via new module parameter /sys/module/cifs/parameters/slow_rsp_threshold or via modprobe: slow_rsp_threshold:Amount of time (in seconds) to wait before logging that a response is delayed. Default: 1 (if set to 0 disables msg). (uint) Signed-off-by: Steve French --- fs/cifs/cifsfs.c | 13 +++++++++++++ fs/cifs/cifsglob.h | 1 + fs/cifs/transport.c | 7 ++++--- 3 files changed, 18 insertions(+), 3 deletions(-) From 225f12c3490d4203201efd3477dee1193c4275d3 Mon Sep 17 00:00:00 2001 From: Steve French Date: Tue, 18 Sep 2018 03:51:23 -0500 Subject: [PATCH 1/2] smb3: add way to control slow response threshold for logging and stats /proc/fs/cifs/Stats when CONFIG_CIFS_STATS2 is enabled logs 'slow' responses, but depending on the server you are debugging a one second timeout may be too fast, so allow setting it to a larger number of seconds via new module parameter /sys/module/cifs/parameters/slow_rsp_threshold or via modprobe: slow_rsp_threshold:Amount of time (in seconds) to wait before logging that a response is delayed. Default: 1 (if set to 0 disables msg). (uint) Signed-off-by: Steve French --- fs/cifs/cifsfs.c | 13 +++++++++++++ fs/cifs/cifsglob.h | 1 + fs/cifs/transport.c | 7 ++++--- 3 files changed, 18 insertions(+), 3 deletions(-) diff --git a/fs/cifs/cifsfs.c b/fs/cifs/cifsfs.c index 7065426b3280..45ea2429ab15 100644 --- a/fs/cifs/cifsfs.c +++ b/fs/cifs/cifsfs.c @@ -81,6 +81,14 @@ module_param(cifs_max_pending, uint, 0444); MODULE_PARM_DESC(cifs_max_pending, "Simultaneous requests to server for " "CIFS/SMB1 dialect (N/A for SMB3) " "Default: 32767 Range: 2 to 32767."); +#ifdef CONFIG_CIFS_STATS2 +unsigned int slow_rsp_threshold = 1; +module_param(slow_rsp_threshold, uint, 0644); +MODULE_PARM_DESC(slow_rsp_threshold, "Amount of time (in seconds) to wait " + "before logging that a response is delayed. " + "Default: 1 (if set to 0 disables msg)."); +#endif /* STATS2 */ + module_param(enable_oplocks, bool, 0644); MODULE_PARM_DESC(enable_oplocks, "Enable or disable oplocks. Default: y/Y/1"); @@ -1418,6 +1426,11 @@ init_cifs(void) #ifdef CONFIG_CIFS_STATS2 atomic_set(&totBufAllocCount, 0); atomic_set(&totSmBufAllocCount, 0); + if (slow_rsp_threshold < 1) + cifs_dbg(FYI, "slow_response_threshold msgs disabled\n"); + else if (slow_rsp_threshold > 32767) + cifs_dbg(VFS, + "slow response threshold set higher than recommended\n"); #endif /* CONFIG_CIFS_STATS2 */ atomic_set(&midCount, 0); diff --git a/fs/cifs/cifsglob.h b/fs/cifs/cifsglob.h index 9dcaed031843..d59588e4aeb4 100644 --- a/fs/cifs/cifsglob.h +++ b/fs/cifs/cifsglob.h @@ -1715,6 +1715,7 @@ GLOBAL_EXTERN atomic_t bufAllocCount; /* current number allocated */ #ifdef CONFIG_CIFS_STATS2 GLOBAL_EXTERN atomic_t totBufAllocCount; /* total allocated over all time */ GLOBAL_EXTERN atomic_t totSmBufAllocCount; +extern unsigned int slow_rsp_threshold; /* number of secs before logging */ #endif GLOBAL_EXTERN atomic_t smBufAllocCount; GLOBAL_EXTERN atomic_t midCount; diff --git a/fs/cifs/transport.c b/fs/cifs/transport.c index b48f43963da6..fe49733766d6 100644 --- a/fs/cifs/transport.c +++ b/fs/cifs/transport.c @@ -113,9 +113,10 @@ DeleteMidQEntry(struct mid_q_entry *midEntry) cifs_small_buf_release(midEntry->resp_buf); #ifdef CONFIG_CIFS_STATS2 now = jiffies; - /* commands taking longer than one second are indications that - something is wrong, unless it is quite a slow link or server */ - if (time_after(now, midEntry->when_alloc + HZ) && + /* commands taking longer than one second (default) can be indications + that something is wrong, unless it is quite a slow link or server */ + if ((slow_rsp_threshold != 0) && + time_after(now, midEntry->when_alloc + slow_rsp_threshold) && (midEntry->command != command)) { /* smb2slowcmd[NUMBER_OF_SMB2_COMMANDS] counts by command */ if ((le16_to_cpu(midEntry->command) < NUMBER_OF_SMB2_COMMANDS) && -- 2.17.1