| Message ID | CAH2r5mv6Rhoz1--hR0pgnbak-40egpgXPgre7BBXLdown=LXGA@mail.gmail.com (mailing list archive) |
|---|---|
| State | New, archived |
| Headers | show |
| Series | smb3: add way to control slow response threshold for logging and stats | expand |
Updated to address problem Aurelien noted (forgot to multiply slow_rsp_threshold by HZ) On Tue, Sep 18, 2018 at 4:10 AM Steve French <smfrench@gmail.com> wrote: > > (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 <stfrench@microsoft.com> > --- > 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) && > -- > > -- > Thanks, > > Steve
From 225f12c3490d4203201efd3477dee1193c4275d3 Mon Sep 17 00:00:00 2001 From: Steve French <stfrench@microsoft.com> 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 <stfrench@microsoft.com> --- 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
(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 <stfrench@microsoft.com> --- fs/cifs/cifsfs.c | 13 +++++++++++++ fs/cifs/cifsglob.h | 1 + fs/cifs/transport.c | 7 ++++--- 3 files changed, 18 insertions(+), 3 deletions(-)