From fcfebb968f4f08ee0dcd07a9b6900eb68e477ee1 Mon Sep 17 00:00:00 2001 From: Bill Zissimopoulos Date: Wed, 26 Aug 2020 14:52:53 -0700 Subject: [PATCH] tools: parselog: parse winfsp logs --- tools/parselog.nim | 318 +++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 318 insertions(+) create mode 100644 tools/parselog.nim diff --git a/tools/parselog.nim b/tools/parselog.nim new file mode 100644 index 00000000..adced145 --- /dev/null +++ b/tools/parselog.nim @@ -0,0 +1,318 @@ +# @file parselog.nim +# +# parse WinFsp debug logs +# +# @copyright 2015-2020 Bill Zissimopoulos + +import algorithm +import macros +import parseopt +import parseutils +import strformat +import strscans +import strutils +import tables + +type + Req = ref object + fsname: string + tid: uint32 + irp: uint64 + op: string + inform: string + context: string + args: seq[(string, string)] + Rsp = ref object + fsname: string + tid: uint32 + irp: uint64 + op: string + status: uint32 + inform: uint + context: string + args: seq[(string, string)] + +proc parseAndAddArg(prefix: string, rest: var string, args: var seq[(string, string)]) = + discard scanf(rest, ",$*", rest) + discard scanf(rest, "$s$*", rest) + var n, v: string + if scanf(rest, "\"$*\"$*", v, rest): + args.add((prefix & "", v)) + elif scanf(rest, "$w=\"$*\"$*", n, v, rest): + args.add((prefix & n, v)) + elif scanf(rest, "$w={$*}$*", n, v, rest): + while "" != v: + parseAndAddArg(n & ".", v, args) + elif scanf(rest, "$w=$*,$*", n, v, rest): + args.add((prefix & n, v)) + elif scanf(rest, "$w=$*$.", n, v): + rest = "" + args.add((prefix & n, v)) + elif scanf(rest, "$*,$*", v, rest): + args.add((prefix & "", v)) + else: + v = rest + rest = "" + args.add((prefix & "", v)) + +proc parseArgs(rest: var string): seq[(string, string)] = + while "" != rest: + parseAndAddArg("", rest, result) + +proc parseReq(op, rest: string): Req = + result = Req(op: op) + var rest = rest + var inform: string + if scanf(rest, "[$+]$s$*", inform, rest): + result.inform = inform + var c0, c1: uint64 + if scanf(rest, "${parseHex[uint64]}:${parseHex[uint64]}$*", c0, c1, rest): + result.context = toHex(c0) & ":" & toHex(c1) + result.args = parseArgs(rest) + +proc parseRsp(op, rest: string): Rsp = + result = Rsp(op: op) + var rest = rest + var status: uint32 + var inform: uint + if scanf(rest, "IoStatus=${parseHex[uint32]}[${parseUint}]$s$*", status, inform, rest): + result.status = status + result.inform = inform + var c0, c1: uint64 + if scanf(rest, "UserContext=${parseHex[uint64]}:${parseHex[uint64]}$*", c0, c1, rest): + result.context = toHex(c0) & ":" & toHex(c1) + result.args = parseArgs(rest) + +proc parseLog(path: string, processReq: proc(req: Req), processRsp: proc(rsp: Rsp)) = + let file = open(path) + defer: file.close() + var lineno = 0 + try: + for line in lines file: + inc lineno + var fsname, dir, op, rest: string + var tid: uint32 + var irp: uint64 + var req: Req + var rsp: Rsp + if scanf(line, "$+[TID=${parseHex[uint32]}]:$s${parseHex[uint64]}:$s$+ $*", + fsname, tid, irp, op, rest): + dir = op[0..1] + op = op[2..^1] + case dir + of ">>": + req = parseReq(op, rest) + req.fsname = fsname + req.tid = tid + req.irp = irp + processReq(req) + of "<<": + rsp = parseRsp(op, rest) + rsp.fsname = fsname + rsp.tid = tid + rsp.irp = irp + processRsp(rsp) + else: + continue + except: + echo &"An exception has occurred while parsing file {path} line {lineno}" + raise + +type + Stat = ref object + ototal: int # open total + oerror: int # open error total + mtotal: int # multiplicate open total + rtotal: int # read total + rbytes: uint64 # read bytes + rerror: int # read error total + wtotal: int # write total + wbytes: uint64 # write bytes + werror: int # write error total + dtotal: int # query directory total + dbytes: uint64 # query directory bytes + derror: int # query directory error total + ptotal: int # query directory w/ pattern total + pbytes: uint64 # query directory w/ pattern bytes + perror: int # query directory w/ pattern error total + ocount: int # current open count +var + reqtab = newTable[uint64, Req]() + filetab = newTable[string, string]() + stattab = newOrderedTable[string, Stat]() + aggr = Stat() + +proc getArg(args: seq[(string, string)], name: string): string = + for n, v in items(args): + if name == n: + return v + +proc processReq(req: Req) = + reqtab[req.irp] = req + case req.op + of "Close": + var filename: string + if filetab.pop(req.context, filename): + var stat = stattab.mgetOrPut(filename, Stat()) + stat.ocount -= 1 + +proc processRsp(rsp: Rsp) = + var req: Req + if reqtab.pop(rsp.irp, req): + doAssert req.op == rsp.op + doAssert req.irp == rsp.irp + case req.op + of "Create": + var filename = getArg(req.args, "") + if "" != filename: + if 0 == rsp.status: + filetab[rsp.context] = filename + var stat = stattab.mgetOrPut(filename, Stat()) + stat.ototal += 1 + aggr.ototal += 1 + stat.ocount += 1 + if 2 == stat.ocount: + stat.mtotal += 1 + aggr.mtotal += 1 + else: + var stat = stattab.mgetOrPut(filename, Stat()) + stat.oerror += 1 + aggr.oerror += 1 + of "Read": + var filename = filetab[req.context] + var stat = stattab.mgetOrPut(filename, Stat()) + if 0 == rsp.status: + stat.rtotal += 1 + stat.rbytes += rsp.inform + aggr.rtotal += 1 + aggr.rbytes += rsp.inform + elif 0xC0000011u32 != rsp.status: + echo &"{rsp.status:X}" + stat.rerror += 1 + aggr.rerror += 1 + of "Write": + var filename = filetab[req.context] + var stat = stattab.mgetOrPut(filename, Stat()) + if 0 == rsp.status: + stat.wtotal += 1 + stat.wbytes += rsp.inform + aggr.wtotal += 1 + aggr.wbytes += rsp.inform + else: + stat.werror += 1 + aggr.werror += 1 + of "QueryDirectory": + var filename = filetab[req.context] + var stat = stattab.mgetOrPut(filename, Stat()) + var pattern = getArg(req.args, "Pattern") + if "NULL" == pattern: + if 0 == rsp.status: + stat.dtotal += 1 + stat.dbytes += rsp.inform + aggr.dtotal += 1 + aggr.dbytes += rsp.inform + else: + stat.derror += 1 + aggr.derror += 1 + else: + if 0 == rsp.status: + stat.ptotal += 1 + stat.pbytes += rsp.inform + aggr.ptotal += 1 + aggr.pbytes += rsp.inform + else: + stat.perror += 1 + aggr.perror += 1 + +macro identName(n: untyped): untyped = + result = n.strVal.newLit + +template dumpstat(F: untyped) = + stattab.sort(proc (x, y: (string, Stat)): int = + cmp(x[1].F, y[1].F), SortOrder.Descending) + var width, rows = 0 + for filename, stat in stattab.pairs: + if 0 == width: + var s = identName(F).toUpperAscii() + width = len($aggr.F) + if width < len(s): + width = len(s) + var f: string + formatValue(f, s, ">" & $width) + echo f, " PER% FILENAME" + var c0, c1: string + formatValue(c0, stat.F, $width) + if 0 != aggr.F: + formatValue(c1, 100.0 * float(stat.F) / float(aggr.F), "5.1f") + else: + c1 = " " + echo c0, " ", c1, " ", filename + inc rows + if opttop == rows: + break + var c0: string + formatValue(c0, aggr.F, $width) + echo c0, " 100.0 TOTAL" + +proc main = + var filenames: seq[string] + var optstat: seq[string] + var opttop = 0 + for kind, key, val in getopt(shortNoVal = {'Z'}, longNoVal = @["Zoo"]): + case kind + of cmdShortOption, cmdLongOption: + case key + of "stat": + optstat.add(val) + of "n": + opttop = parseInt(val) + of cmdArgument: + filenames.add(key) + else: + discard + if 0 == len(optstat): + optstat.add("ototal") + + if 0 == len(filenames): + stderr.writeLine("usage: parselog [-nNN] [--stat ototal|rtotal|wtotal|dtotal|...] file...") + quit(2) + + for filename in filenames: + parseLog filename, processReq, processRsp + + for s in optstat: + case s + of "ototal": + dumpstat ototal + of "oerror": + dumpstat oerror + of "mtotal": + dumpstat mtotal + of "rtotal": + dumpstat rtotal + of "rbytes": + dumpstat rbytes + of "rerror": + dumpstat rerror + of "wtotal": + dumpstat wtotal + of "wbytes": + dumpstat wbytes + of "werror": + dumpstat werror + of "dtotal": + dumpstat dtotal + of "dbytes": + dumpstat dbytes + of "derror": + dumpstat derror + of "ptotal": + dumpstat ptotal + of "pbytes": + dumpstat pbytes + of "perror": + dumpstat perror + echo "" + +when isMainModule: + main()