[RFC][PATCH] Track time spent in each command

[ronnie sahlberg]

Very nice.
But maybe min and max to each command as well.
I have all three of min/max/avg is very useful.

At least avg and max will tell you if there are any abnormal outliers.

On Tue, Mar 26, 2019 at 3:39 PM Steve French <smfrench at gmail.com> wrote:
>
> 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
>
> --
> Thanks,
>
> Steve