From 60396eccc04bbecfc85404ce10903610e082517d Mon Sep 17 00:00:00 2001
From: Steve French <stfrench@microsoft.com>
Date: Mon, 19 Oct 2020 18:18:15 -0500
Subject: [PATCH] smb3: add dynamic trace point to trace when credits obtained
MIME-Version: 1.0
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: 8bit
SMB3 crediting is used for flow control, and it can be useful to
trace for problem determination how many credits were acquired
and for which operation.
Here is an example ("trace-cmd record -e *add_credits"):
cifsd-9522 [010] .... 5995.202712: smb3_add_credits:
server=localhost current_mid=0x12 credits=373 credits_to_add=10
cifsd-9522 [010] .... 5995.204040: smb3_add_credits:
server=localhost current_mid=0x15 credits=400 credits_to_add=30
Signed-off-by: Steve French <stfrench@microsoft.com>
---
fs/cifs/smb2ops.c | 4 +++-
fs/cifs/trace.h | 18 ++++++++++++------
fs/cifs/transport.c | 5 +++--
3 files changed, 18 insertions(+), 9 deletions(-)
@@ -72,7 +72,7 @@ smb2_add_credits(struct TCP_Server_Info *server,
/* eg found case where write overlapping reconnect messed up credits */
if (((optype & CIFS_OP_MASK) == CIFS_NEG_OP) && (*val != 0))
trace_smb3_reconnect_with_invalid_credits(server->CurrentMid,
- server->hostname, *val);
+ server->hostname, *val, add);
if ((instance == 0) || (instance == server->reconnect_instance))
*val += add;
else
@@ -121,6 +121,8 @@ smb2_add_credits(struct TCP_Server_Info *server,
cifs_dbg(FYI, "disabling oplocks\n");
break;
default:
+ trace_smb3_add_credits(server->CurrentMid,
+ server->hostname, rc, add);
cifs_dbg(FYI, "add %u credits total=%d\n", add, rc);
}
}
@@ -878,33 +878,39 @@ DEFINE_SMB3_RECONNECT_EVENT(partial_send_reconnect);
DECLARE_EVENT_CLASS(smb3_credit_class,
TP_PROTO(__u64 currmid,
char *hostname,
- int credits),
- TP_ARGS(currmid, hostname, credits),
+ int credits,
+ int credits_to_add),
+ TP_ARGS(currmid, hostname, credits, credits_to_add),
TP_STRUCT__entry(
__field(__u64, currmid)
__field(char *, hostname)
__field(int, credits)
+ __field(int, credits_to_add)
),
TP_fast_assign(
__entry->currmid = currmid;
__entry->hostname = hostname;
__entry->credits = credits;
+ __entry->credits_to_add = credits_to_add;
),
- TP_printk("server=%s current_mid=0x%llx credits=%d",
+ TP_printk("server=%s current_mid=0x%llx credits=%d credits_to_add=%d",
__entry->hostname,
__entry->currmid,
- __entry->credits)
+ __entry->credits,
+ __entry->credits_to_add)
)
#define DEFINE_SMB3_CREDIT_EVENT(name) \
DEFINE_EVENT(smb3_credit_class, smb3_##name, \
TP_PROTO(__u64 currmid, \
char *hostname, \
- int credits), \
- TP_ARGS(currmid, hostname, credits))
+ int credits, \
+ int credits_to_add), \
+ TP_ARGS(currmid, hostname, credits, credits_to_add))
DEFINE_SMB3_CREDIT_EVENT(reconnect_with_invalid_credits);
DEFINE_SMB3_CREDIT_EVENT(credit_timeout);
+DEFINE_SMB3_CREDIT_EVENT(add_credits);
#endif /* _CIFS_TRACE_H */
@@ -563,7 +563,7 @@ wait_for_free_credits(struct TCP_Server_Info *server, const int num_credits,
cifs_num_waiters_dec(server);
if (!rc) {
trace_smb3_credit_timeout(server->CurrentMid,
- server->hostname, num_credits);
+ server->hostname, num_credits, 0);
cifs_server_dbg(VFS, "wait timed out after %d ms\n",
timeout);
return -ENOTSUPP;
@@ -604,7 +604,8 @@ wait_for_free_credits(struct TCP_Server_Info *server, const int num_credits,
if (!rc) {
trace_smb3_credit_timeout(
server->CurrentMid,
- server->hostname, num_credits);
+ server->hostname, num_credits,
+ 0);
cifs_server_dbg(VFS, "wait timed out after %d ms\n",
timeout);
return -ENOTSUPP;
--
2.25.1
Added dynamic trace point to trace getting credits. See attached patch. Here is an example of what you see in mount # TASK-PID CPU# |||| TIMESTAMP FUNCTION # | | | |||| | | cifsd-9522 [010] .... 5995.187999: smb3_add_credits: server=localhost current_mid=0x4 credits=193 credits_to_add=64 cifsd-9522 [010] .... 5995.196028: smb3_add_credits: server=localhost current_mid=0x5 credits=256 credits_to_add=64 cifsd-9522 [010] .... 5995.197886: smb3_add_credits: server=localhost current_mid=0x7 credits=274 credits_to_add=20 cifsd-9522 [010] .... 5995.198111: smb3_add_credits: server=localhost current_mid=0x8 credits=283 credits_to_add=10 cifsd-9522 [010] .... 5995.198327: smb3_add_credits: server=localhost current_mid=0x9 credits=292 credits_to_add=10 cifsd-9522 [010] .... 5995.198533: smb3_add_credits: server=localhost current_mid=0xa credits=301 credits_to_add=10 cifsd-9522 [010] .... 5995.198744: smb3_add_credits: server=localhost current_mid=0xb credits=310 credits_to_add=10 cifsd-9522 [010] .... 5995.199056: smb3_add_credits: server=localhost current_mid=0xc credits=319 credits_to_add=10 cifsd-9522 [010] .... 5995.199436: smb3_add_credits: server=localhost current_mid=0xd credits=328 credits_to_add=10 cifsd-9522 [010] .... 5995.199872: smb3_add_credits: server=localhost current_mid=0xe credits=337 credits_to_add=10 cifsd-9522 [010] .... 5995.201286: smb3_add_credits: server=localhost current_mid=0xf credits=346 credits_to_add=10 cifsd-9522 [010] .... 5995.201500: smb3_add_credits: server=localhost current_mid=0x10 credits=355 credits_to_add=10 cifsd-9522 [010] .... 5995.202504: smb3_add_credits: server=localhost current_mid=0x11 credits=364 credits_to_add=10 cifsd-9522 [010] .... 5995.202712: smb3_add_credits: server=localhost current_mid=0x12 credits=373 credits_to_add=10 cifsd-9522 [010] .... 5995.204040: smb3_add_credits: server=localhost current_mid=0x15 credits=400 credits_to_add=30