From patchwork Mon Oct 19 23:23:40 2020 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 8bit X-Patchwork-Submitter: Steve French X-Patchwork-Id: 1384533 Return-Path: X-Original-To: incoming@patchwork.ozlabs.org Delivered-To: patchwork-incoming@bilbo.ozlabs.org Authentication-Results: ozlabs.org; spf=pass (sender SPF authorized) smtp.mailfrom=vger.kernel.org (client-ip=23.128.96.18; helo=vger.kernel.org; envelope-from=linux-cifs-owner@vger.kernel.org; receiver=) Authentication-Results: ozlabs.org; dmarc=pass (p=none dis=none) header.from=gmail.com Authentication-Results: ozlabs.org; dkim=pass (2048-bit key; unprotected) header.d=gmail.com header.i=@gmail.com header.a=rsa-sha256 header.s=20161025 header.b=Ih6iVMdd; dkim-atps=neutral Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by ozlabs.org (Postfix) with ESMTP id 4CFXrX2Zhfz9sSC for ; Tue, 20 Oct 2020 10:23:56 +1100 (AEDT) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S2388927AbgJSXXz (ORCPT ); Mon, 19 Oct 2020 19:23:55 -0400 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:40736 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1729612AbgJSXXz (ORCPT ); Mon, 19 Oct 2020 19:23:55 -0400 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 65C7FC0613CE for ; Mon, 19 Oct 2020 16:23:53 -0700 (PDT) Received: by mail-lf1-x133.google.com with SMTP id 184so2113484lfd.6 for ; Mon, 19 Oct 2020 16:23:53 -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; bh=a2vylIKuPHdrO9GEKfz/AuFuzvGr6eI7GS2n1PdgQ4U=; b=Ih6iVMddsC0JKWh2hsFUcdPs0NLKaE4Vcn430WMya1rvsdUNcrerkZxZk8RVc/e6vD nvraKDeKxF+MPTcUKoPxDbkmY/oHjgqAyNIlHYiqu97+lLYOOqR1LLPJNa88vqZDu+hE 0lMxpHT2gchZlCeBIB/8YG+oTef1lFwS32necM8g8nU12GQ3WHAdNm0Hccg8vdUV2vIL dgqiHvgRCTk/z8yI13YGy3B+FdFYhDj8YW/Jn5nvmQ79LsK0GzLFpJoegFAs8tc/JLNG FMCke311U4nVAXlwAlvqYysAhMq3SivGEu/BSMzzkb/ZZIddF+/+9icjaIWsP8ySHCsD Y2sA== 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=a2vylIKuPHdrO9GEKfz/AuFuzvGr6eI7GS2n1PdgQ4U=; b=lzljxH3DCwg+LMf4oVgsoXgKSsD5SaHDXJYzLrI+CSgEVpCWxd0FOQRpaxiaJiuUw+ UzmkgmPpHf5Hj/z02LdO7yNJ9cUA9lec5i6CqlJCcW+ZUQmOmDugOSBRYVQ7bnJOVMrs dQ91PeEFWQQM2Lj3dwpb34Gl7B308ytjPYtHNWsvaCunWFM2UZRc7TgOHQUS1C131RfB 0LpIwko1nDdE2ywHE90+pHNojg3g8vV5cUzXYsN6bXQ/w9GcntrJsSldpBS0UL9tPw4t 38vxJuAebuEKrGpjZxp9ebw6qYN+GHXDwbgcPs7dxf+mV6qN2zWgmy2qhybTCm8RZv51 oyEw== X-Gm-Message-State: AOAM531KH2wDlcYy9fjCLzD7HdASiA6zvC1CyBYvtLJRw25rq8oOcJYj 06cSHlSDM0fDYWCbLCQUoW+J3yn0stOWdAXVTN8ULO3k9JIi1A== X-Google-Smtp-Source: ABdhPJzQ9vuJszXEE/Q45SLAJ4de597VZx/JdIkzZPHc2h31T55zzIX6WVxBMXlh5df4yA0myoL2GfLvXk+4yIN1DZ8= X-Received: by 2002:a19:241:: with SMTP id 62mr706912lfc.165.1603149831564; Mon, 19 Oct 2020 16:23:51 -0700 (PDT) MIME-Version: 1.0 From: Steve French Date: Mon, 19 Oct 2020 18:23:40 -0500 Message-ID: Subject: [SMB3][PATCH] add dynamic trace point to trace when credits obtained To: CIFS Precedence: bulk List-ID: X-Mailing-List: linux-cifs@vger.kernel.org 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 Reviewed-by: Aurelien Aptel From 60396eccc04bbecfc85404ce10903610e082517d Mon Sep 17 00:00:00 2001 From: Steve French 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 --- fs/cifs/smb2ops.c | 4 +++- fs/cifs/trace.h | 18 ++++++++++++------ fs/cifs/transport.c | 5 +++-- 3 files changed, 18 insertions(+), 9 deletions(-) diff --git a/fs/cifs/smb2ops.c b/fs/cifs/smb2ops.c index 0dfa832a3de0..f085fe32c342 100644 --- a/fs/cifs/smb2ops.c +++ b/fs/cifs/smb2ops.c @@ -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); } } diff --git a/fs/cifs/trace.h b/fs/cifs/trace.h index eef4b08c7208..90e0fab69bb8 100644 --- a/fs/cifs/trace.h +++ b/fs/cifs/trace.h @@ -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 */ diff --git a/fs/cifs/transport.c b/fs/cifs/transport.c index ac7632482736..e27e255d40dd 100644 --- a/fs/cifs/transport.c +++ b/fs/cifs/transport.c @@ -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