From patchwork Tue Mar 26 05:39:07 2019 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Steve French X-Patchwork-Id: 10870419 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 7321C922 for ; Tue, 26 Mar 2019 05:39:21 +0000 (UTC) Received: from mail.wl.linuxfoundation.org (localhost [127.0.0.1]) by mail.wl.linuxfoundation.org (Postfix) with ESMTP id 5414228676 for ; Tue, 26 Mar 2019 05:39:21 +0000 (UTC) Received: by mail.wl.linuxfoundation.org (Postfix, from userid 486) id 45012286AD; Tue, 26 Mar 2019 05:39:21 +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 9C64E28676 for ; Tue, 26 Mar 2019 05:39:20 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1726238AbfCZFjU (ORCPT ); Tue, 26 Mar 2019 01:39:20 -0400 Received: from mail-pg1-f171.google.com ([209.85.215.171]:39805 "EHLO mail-pg1-f171.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1725308AbfCZFjT (ORCPT ); Tue, 26 Mar 2019 01:39:19 -0400 Received: by mail-pg1-f171.google.com with SMTP id k3so4019579pga.6 for ; Mon, 25 Mar 2019 22:39:19 -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=elsXBbk1LfyEYkdCb5vuOfeN72A9fcQwCW1I7/Chw1s=; b=Jwgs6SWR+SnDcppQJd4+2wAalugNMk0H18VR3rHtkuATu1ED3OJkRYV7ADVG5qxgVm TxXz5UxmLC1EOuC68rYG/C7X2z+HmDCVLKL2QIfAnLuqcwTkt/MQsmOskEtjiylP3RjV EsE5sDLoBGfNhjCRv2P0ruIk6hgj/eyTaZCAsrOMqC3DWqlQn30FWqv65rIflotq2jsA 9XejSlp/PYM48vC7KhykOuFZKe4FPnTaSndePNOfZCCIUoicsath40Bgsu/3Fc1o9jBg iBu7FVgV32HIHSZ0D+e0y2iWv56B24ygTaAYCdTEu3XDFGh7DkEPZH/wjOUGYzh4cIGO yQ3g== 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=elsXBbk1LfyEYkdCb5vuOfeN72A9fcQwCW1I7/Chw1s=; b=YkNi19UtCYLiYxD0QREpRLgupZL6d1ktMaZoLMLgCHfi6IQyf6WeDI75zsRj/bWyw6 utYelnOqtGJR6KxhDw+Tqbaowh3+pbvbB3DCKniqV1aWHzWxbJycymU+bDVUp16eis4y 4Rn0HrEWAP4pwO42G38NC1Uib1+X/dkh6c0kcRJ6+hp7cAMFZwIg7Ez70cxMOgLvE9O5 WfF8JwiEeuyajg0KnLiTjlt1z3EH+SXiy9xsyhKSzCal5njppJlHsgGGLZZGntI/wz+e BR2Ru2DD/Zi/AXozyRujWHKFlVWkwx85Ab/AQCyzrTmPwyrOgNaYBQu4/4S4TciVxblM IZXQ== X-Gm-Message-State: APjAAAW3bDiFt9K8Px3xUzzqPN8ot0Pu9aAi3mIqaFXPBGdQQjvBZTzx eZnHEwp0Fk+TTS+pUCBlGefZiVLV7U3Zumr/mU+xhSDH X-Google-Smtp-Source: APXvYqyeSBkLGyOJTWbgPLVjyUdT/xasRk9XdvGvD549GBil1QUBK1WyBE6u23zYYB9JNQTIoOGRk72KBjVkupxkWGY= X-Received: by 2002:a63:31ce:: with SMTP id x197mr27336224pgx.69.1553578758514; Mon, 25 Mar 2019 22:39:18 -0700 (PDT) MIME-Version: 1.0 From: Steve French Date: Tue, 26 Mar 2019 00:39:07 -0500 Message-ID: Subject: [RFC][PATCH] Track time spent in each command To: CIFS , samba-technical 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 I created a small experimental patch (leveraging the existing code for the slow command check we already have in mid processing) to track the total time per SMB2/SMB3 command. Seems like it could be useful - here is sample output (see below) from running seven xfstests to generate the stats (these stats require CONFIG_CIFS_STATS2 to be compiled as do the slow command counters). I wanted to keep the patch small and low risk so this seemed like the best place to capture it. This could be helpful in calculating average time per command (and perhaps help isolate performance problems, and isolate what is really causing slowdowns). As with other counters: "echo 0 > /proc/fs/cifs/Stats" resets them. The new stats counters start at the line "Total time spent processing each command" Thoughts? $ cat /proc/fs/cifs/Stats Resources in use CIFS Session: 1 Share (unique mount targets): 3 SMB Request/Response Buffer: 1 Pool size: 5 SMB Small Req/Resp Buffer: 2 Pool size: 30 Total Large 60864 Small 1165977 Allocations Operations (MIDs): 1 0 session 0 share reconnects Total vfs operations: 280236 maximum at one time: 3 Total time spent processing each command cmd: 0 jiffies: 0 seconds 0 cmd: 1 jiffies: 2 seconds 0 cmd: 2 jiffies: 0 seconds 0 cmd: 3 jiffies: 1 seconds 0 cmd: 4 jiffies: 1 seconds 0 cmd: 5 jiffies: 6212 seconds 24 cmd: 6 jiffies: 3993 seconds 15 cmd: 7 jiffies: 135 seconds 0 cmd: 8 jiffies: 83 seconds 0 cmd: 9 jiffies: 44 seconds 0 cmd: 10 jiffies: 0 seconds 0 cmd: 11 jiffies: 1 seconds 0 cmd: 12 jiffies: 0 seconds 0 cmd: 13 jiffies: 0 seconds 0 cmd: 14 jiffies: 47 seconds 0 cmd: 15 jiffies: 0 seconds 0 cmd: 16 jiffies: 1890 seconds 7 cmd: 17 jiffies: 1368 seconds 5 cmd: 18 jiffies: 0 seconds 0 1) \\localhost\btrfs-scratch SMBs: 42255 Bytes read: 25379425 Bytes written: 53689661 Open files: 1 total (local), 1 open on server TreeConnects: 1 total 0 failed TreeDisconnects: 0 total 0 failed Creates: 14012 total 0 failed Closes: 14009 total 0 failed Flushes: 27 total 0 failed Reads: 41 total 0 failed Writes: 112 total 0 failed Locks: 0 total 0 failed IOCTLs: 2 total 1 failed QueryDirectories: 28 total 0 failed ChangeNotifies: 0 total 0 failed QueryInfos: 11312 total 0 failed SetInfos: 2711 total 0 failed OplockBreaks: 0 sent 0 failed 2) \\localhost\btrfs SMBs: 77 Bytes read: 282 Bytes written: 94 Open files: 0 total (local), 0 open on server TreeConnects: 1 total 0 failed TreeDisconnects: 0 total 0 failed Creates: 23 total 0 failed Closes: 21 total 0 failed Flushes: 0 total 0 failed Reads: 3 total 0 failed Writes: 1 total 0 failed Locks: 0 total 0 failed From 3f1ea43711cc8298263323a25e26227cbb22873d Mon Sep 17 00:00:00 2001 From: Steve French Date: Tue, 26 Mar 2019 00:32:31 -0500 Subject: [PATCH] SMB3: track total time spent per command This allows us to calculate average time spent in each SMB2/SMB3 command and also helps determine where bottlenecks could be. Signed-off-by: Steve French --- fs/cifs/cifs_debug.c | 9 ++++++++- fs/cifs/cifsglob.h | 3 ++- fs/cifs/transport.c | 3 +++ 3 files changed, 13 insertions(+), 2 deletions(-) diff --git a/fs/cifs/cifs_debug.c b/fs/cifs/cifs_debug.c index 13c1288b04a7..8fcfc7770ebb 100644 --- a/fs/cifs/cifs_debug.c +++ b/fs/cifs/cifs_debug.c @@ -462,8 +462,10 @@ static ssize_t cifs_stats_proc_write(struct file *file, server = list_entry(tmp1, struct TCP_Server_Info, tcp_ses_list); #ifdef CONFIG_CIFS_STATS2 - for (i = 0; i < NUMBER_OF_SMB2_COMMANDS; i++) + for (i = 0; i < NUMBER_OF_SMB2_COMMANDS; i++) { atomic_set(&server->smb2slowcmd[i], 0); + server->time_per_cmd[i] = 0; + } #endif /* CONFIG_CIFS_STATS2 */ list_for_each(tmp2, &server->smb_ses_list) { ses = list_entry(tmp2, struct cifs_ses, @@ -531,6 +533,11 @@ static int cifs_stats_proc_show(struct seq_file *m, void *v) server = list_entry(tmp1, struct TCP_Server_Info, tcp_ses_list); #ifdef CONFIG_CIFS_STATS2 + seq_printf(m, "Total time spent processing each command\n"); + for (j = 0; j < NUMBER_OF_SMB2_COMMANDS; j++) + seq_printf(m, "cmd: %d jiffies: %llu seconds %llu\n", j, + server->time_per_cmd[j], + server->time_per_cmd[j]/HZ); for (j = 0; j < NUMBER_OF_SMB2_COMMANDS; j++) if (atomic_read(&server->smb2slowcmd[j])) seq_printf(m, "%d slow responses from %s for command %d\n", diff --git a/fs/cifs/cifsglob.h b/fs/cifs/cifsglob.h index 38feae812b47..7232788fffc0 100644 --- a/fs/cifs/cifsglob.h +++ b/fs/cifs/cifsglob.h @@ -18,7 +18,7 @@ */ #ifndef _CIFS_GLOB_H #define _CIFS_GLOB_H - +#define CONFIG_CIFS_STATS2 1 /* BB REMOVEME */ #include #include #include @@ -708,6 +708,7 @@ struct TCP_Server_Info { atomic_t in_send; /* requests trying to send */ atomic_t num_waiters; /* blocked waiting to get in sendrecv */ atomic_t smb2slowcmd[NUMBER_OF_SMB2_COMMANDS]; /* count resps > 1 sec */ + __u64 time_per_cmd[NUMBER_OF_SMB2_COMMANDS]; /* total time per cmd */ #endif /* STATS2 */ unsigned int max_read; unsigned int max_write; diff --git a/fs/cifs/transport.c b/fs/cifs/transport.c index 1de8e996e566..0c7f264403bd 100644 --- a/fs/cifs/transport.c +++ b/fs/cifs/transport.c @@ -114,6 +114,9 @@ DeleteMidQEntry(struct mid_q_entry *midEntry) cifs_small_buf_release(midEntry->resp_buf); #ifdef CONFIG_CIFS_STATS2 now = jiffies; + if (le16_to_cpu(midEntry->command) < NUMBER_OF_SMB2_COMMANDS) + midEntry->server->time_per_cmd[le16_to_cpu(midEntry->command)] + += (now - midEntry->when_alloc); /* * commands taking longer than one second (default) can be indications * that something is wrong, unless it is quite a slow link or a very -- 2.17.1