From 472d9c3adca5b95f2164b6bc310f9b546aeaaa5e Mon Sep 17 00:00:00 2001 From: Amin Yahyaabadi Date: Mon, 5 Jul 2021 14:21:42 -0500 Subject: [PATCH] Revert the breakage --- dub.json | 17 +- source/app.d | 159 ++++++++++++++++- source/profdump.d | 435 ++++++++++++++++++++++++++++++++++++++++------ 3 files changed, 538 insertions(+), 73 deletions(-) diff --git a/dub.json b/dub.json index 24f5909..06122f2 100644 --- a/dub.json +++ b/dub.json @@ -5,20 +5,5 @@ ], "description": "Converts profiler output to DOT graph, JSON or human-readable plain text", "copyright": "Copyright © 2017, Anton Fediusin", - "license": "MIT", - "dependencies": { - "emsi_containers": "~>0.8.0-alpha.9" - }, - "configurations": [ - { - "name": "executable" - }, - { - "name": "unittest", - "dependencies": { - "silly": {"path": "../silly"}, - "fluent-asserts": "" - } - } - ] + "license": "MIT" } diff --git a/source/app.d b/source/app.d index a158b63..577aae8 100644 --- a/source/app.d +++ b/source/app.d @@ -1,5 +1,156 @@ -version(unittest) { +import std.stdio; +import std.getopt; +import std.file : exists; +import std.format : format; +import profdump; -} else { - void main() { assert(0, "TODO"); } -} \ No newline at end of file +int main(string[] args) { + File input = stdin; + File output = stdout; + bool pretty = true; + bool force = false; + bool verbose = false; + float threshold = 0.0; + enum TARGET : ubyte { + nul, + json, + plain, + dot, + blame + } + TARGET target = TARGET.nul; + string[float] colour; + string[float] colourDefault = [ + 0: "limegreen", + 10: "slateblue", + 25: "steelblue", + 50: "royalblue", + 75: "navy", + 95: "red" + ]; + + void setTarget(string option) { + if(option == "json|j") { + target = TARGET.json; + } else if(option == "plain|p") { + target = TARGET.plain; + } else if(option == "dot|d") { + target = TARGET.dot; + } else if(option == "blame|b") { + target = TARGET.blame; + } + } + auto result = args.getopt( + std.getopt.config.stopOnFirstNonOption, + std.getopt.config.bundling, + "plain|p", "print detailed information about functions (default)", &setTarget, + "json|j", "print JSON", &setTarget, + "dot|d", "output dot graph", &setTarget, + "blame|b", "print list of functions ordered by time", &setTarget, + "threshold|t", "(%% of main function) hide functions below this threshold (default: %1.1f)" + .format(threshold), &threshold, + "pretty", "prettify JSON output (default: true)", &pretty, + "colour", "customize colours of dot graph nodes (default: %s)" + .format(colourDefault), &colour, + "force|f", "overwrite output file if exists", &force, + "verbose|v", "do not minimize function names", &verbose + ); + + if(colour.length == 0) + colour = colourDefault; + + if(result.helpWanted) { + return help(result); + } + + if(args.length <= 1) { + if(exists("trace.log")) { + input = File("trace.log", "r"); + } else { + stderr.writeln("'trace.log' not found, input file not specified"); + return help(result); + } + } else { + if(args[1] == "-") { + input = stdin; + } else { + if(exists(args[1])) { + input = File(args[1], "r"); + } else { + stderr.writefln("File '%s' does not exist", args[1]); + return help(result); + } + } + } + + if(args.length > 2) { + if(args[2] == "-") { + output = stdout; + } else { + if(exists(args[2]) && !force) { + stderr.writefln("File '%s' already exists. Specify other file or pass '-f' option", args[2]); + return help(result); + } else { + output = File(args[2], "w"); + } + } + } + + auto prof = Profile(input, verbose); + + final switch(target) with (TARGET) { + case json: + prof.writeJSON(output, threshold, pretty); + return 0; + case plain: case nul: + prof.writeString(output, threshold); + return 0; + case dot: + prof.writeDOT(output, threshold, colour); + return 0; + case blame: { + import std.algorithm : sort; + import std.string : leftJustify; + + HASH[float] funcs; + foreach(k, ref unused; prof.Functions) { + auto perc = prof.percOf(k); + if(threshold == 0 || perc >= threshold) + funcs[perc] = k; + } + if(verbose) { + foreach(k; sort!"a > b"(funcs.keys)) + output.writefln("%s\t%3.5fs %3.2f%%\t%3.5fs %3.2f%%", + prof.Functions[funcs[k]] + .Name + .leftJustify(40), + prof.timeOf(funcs[k]), + prof.percOf(funcs[k]), + prof.functionTimeOf(funcs[k]), + prof.functionPercOf(funcs[k])); + } else { + foreach(k; sort!"a > b"(funcs.keys)) + output.writefln("%s\t%3.5fs %3.2f%%", + prof.Functions[funcs[k]] + .Name + .leftJustify(40), + prof.timeOf(funcs[k]), + prof.percOf(funcs[k])); + } + return 0; + } + } +} + +enum HELPTEXT = "Usage: profdump [options] [input file] [output file]\n" ~ +"Converts the output of dlang compiler into a plain text, json or dot graph.\n" ~ +"If input file is not specified, looks for 'trace.log' file.\n" ~ +"You can set input and output file to stdin/stdout by passing '-' instead of file name.\n" ~ +"\n" ~ +"Options:"; + + +int help(ref GetoptResult result) { + defaultGetoptPrinter(HELPTEXT, result.options); + return 0; +} diff --git a/source/profdump.d b/source/profdump.d index 920363b..a14b14e 100644 --- a/source/profdump.d +++ b/source/profdump.d @@ -1,82 +1,411 @@ module profdump; -import containers; +import std.algorithm : canFind; +import std.stdio : File; +import std.string : indexOfAny, indexOfNeither; +import std.conv : to; +import std.regex : regex, matchFirst, replaceAll; +import std.json : JSONValue; +import std.exception : enforce; alias HASH = ubyte[4]; -import std.typecons : RefCounted; +private char[] demangle(const(char)[] buf, bool verbose = false) { + static import core.demangle; + if(buf == "_Dmain".dup) { + return "void main()".dup; + } else { + if(verbose) { + return core.demangle.demangle(buf); + } else { + return core.demangle.demangle(buf) + .replaceAll(regex(r"(?:@\w+\s|pure\s|nothrow\s)", "g"), "") + .replaceAll(regex(r"\([ ,*A-Za-z0-9\(\)!\[\]@]+\)", "g"), "(..)"); + } + } +} + +struct Profile { + Function[HASH] Functions; + ulong TicksPerSecond; + float TimeOfMain; + + this(ref File f, bool verbose = false) { + import std.digest.crc : crc32Of; -alias String = RefCounted!(DynamicArray!char); + Function temp; + bool newEntry = false; + foreach(ref line; f.byLine) { + if(line.length == 0) { + continue; + } else if(line[0] == '-') { + newEntry = true; + if(temp.Name.length != 0) { + this.Functions[temp.Mangled.crc32Of] = temp; + temp = Function(); + } + } else if(line[0] == '=') { + if(temp.Name.length != 0) + this.Functions[temp.Mangled.crc32Of] = temp; + auto i = line.indexOfAny("0123456789"); + if (i == -1 && line.canFind("Megaticks")) { + // timing is in Megaticks. See: druntime/rt/trace.d + this.TicksPerSecond = 1_000_000; + } else { + enforce(i > 0, + "Your trace.log file is invalid"); + auto s = line[i..$].indexOfNeither("0123456789"); + this.TicksPerSecond = line[i..i + s].to!ulong; + } + break; + } else if(line[0] == '\t') { + auto cap = line.matchFirst( + regex(r"\t\s*(\d+)\t\s*(\w+)")); + enforce(!cap.empty, + "Your trace.log file is invalid"); + if(newEntry) { + temp.calledBy(FunctionElement( + cap[2].demangle(verbose).dup, + cap[2].dup, + cap[1].to!ulong)); + } else { + temp.callsTo(FunctionElement( + cap[2].demangle(verbose).dup, + cap[2].dup, + cap[1].to!ulong)); + } + } else { + auto cap = line.matchFirst( + regex(r"(\w+)\t\s*-?(\d+)\t\s*-?(\d+)\t\s*-?(\d+)")); + assert(!cap.empty); + newEntry = false; + temp.Name = cap[1].demangle(verbose).dup; + temp.Mangled = cap[1].dup; + temp.Calls = cap[2].to!ulong; + temp.FunctionTime = cap[4].to!ulong; + temp.Time = cap[3].to!ulong; + } + } -struct Function { - private { - String m_name; - ulong m_calls; + const HASH main = "_Dmain".crc32Of; + enforce(main in this.Functions, + "Your trace.log file is invalid"); + + this.TimeOfMain = this.timeOf(main); } - this(string name, ulong calls = 0) { - m_name.reserve(name.length); - foreach(ref c; name) - m_name ~= c; - m_calls = calls; + const void writeString(ref File f, in float threshold = 0) { + foreach(k, ref v; this.Functions) { + if(threshold != 0 && this.percOf(k) < threshold) + continue; + f.writefln("Function '%s':\n"~ + "\tMangled name: '%s'", + v.Name, + v.Mangled); + + if(v.CallsTo) { + f.writeln("\tCalls:"); + foreach(ke, va; v.CallsTo) + f.writefln("\t\t%s\t%d %s", va.Name, va.Calls, + va.Calls == 1 ? "time" : "times"); + } + if(v.CalledBy) { + f.writeln("\tCalled by:"); + foreach(ke, va; v.CalledBy) + f.writefln("\t\t%s\t%d %s", va.Name, va.Calls, + va.Calls == 1 ? "time" : "times"); + } + f.writefln("\tTook: %f seconds (%f%%)\n"~ + "\tFinished in: %f seconds (%f%%)", + this.functionTimeOf(k), + this.functionPercOf(k), + this.timeOf(k), + this.percOf(k)); + } } - this(String name, ulong calls = 0) { - m_name = name; - m_calls = calls; + deprecated const void toString(scope void delegate(const(char)[]) s, in float threshold = 0) { + import std.format : format; + foreach(k, ref v; this.Functions) { + if(threshold != 0 && this.percOf(k) < threshold) + continue; + s("Function '%s':\n".format(v.Name)); + s("\tMangled name: '%s'\n".format(v.Mangled)); + if(v.CallsTo) { + s("\tCalls:\n"); + foreach(ke, va; v.CallsTo) + s("\t\t%s\t%d times\n".format(va.Name, va.Calls)); + } + if(v.CalledBy) { + s("\tCalled by:\n"); + foreach(ke, va; v.CalledBy) + s("\t\t%s\t%d times\n".format(va.Name, va.Calls)); + } + s("\tTook: %f seconds (%f%%)\n" + .format(this.functionTimeOf(k), this.functionPercOf(k))); + s("\tFinished in: %f seconds (%f%%)\n" + .format(this.timeOf(k), this.percOf(k))); + } } -@property: - auto name() { return m_name; } - void name(String m) { m_name = m; } + deprecated const void toJSONString(scope void delegate(const(char)[]) s, + in float threshold = 0, + in bool pretty = false) { + if(pretty) { + s(this.toJSON(threshold).toPrettyString); + s("\n"); + } else { + s(this.toJSON(threshold).toString); + } + } - auto calls() { return m_calls; } - void calls(ulong c) { m_calls = c; } + const void writeJSON(ref File f, in float threshold = 0, in bool pretty = false) { + (pretty) + ? f.writeln(this.toJSON(threshold).toPrettyString) + : f.write(this.toJSON(threshold).toString); + } - HASH hashOf() { - import std.digest.murmurhash : MurmurHash3; - import std.digest : digest; + const JSONValue toJSON(in float threshold = 0) { + JSONValue[] ret; + foreach(k, ref v; this.Functions) { + if(threshold != 0 && this.percOf(k) < threshold) + continue; - return m_name[].digest!(MurmurHash3!32); + JSONValue func = JSONValue([ + "name": v.Name, + "mangled": v.Mangled + ]); + if(v.CallsTo) { + JSONValue[] temp; + foreach(kk, vv; v.CallsTo) { + temp ~= JSONValue([ + "name": JSONValue(vv.Name), + "mangled": JSONValue(vv.Mangled), + "calls": JSONValue(vv.Calls) + ]); + } + func["callsTo"] = JSONValue(temp); + } + if(v.CalledBy) { + JSONValue[] temp; + foreach(k, vv; v.CalledBy) { + temp ~= JSONValue([ + "name": JSONValue(vv.Name), + "mangled": JSONValue(vv.Mangled), + "calls": JSONValue(vv.Calls) + ]); + } + func["calledBy"] = JSONValue(temp); + } + func["functionTimeSec"] = JSONValue(this.functionTimeOf(k)); + func["timeSec"] = JSONValue(this.timeOf(k)); + func["functionTime"] = JSONValue(v.FunctionTime); + func["time"] = JSONValue(v.Time); + func["functionPerc"] = JSONValue(this.functionPercOf(k)); + func["perc"] = JSONValue(this.percOf(k)); + + ret ~= func; + } + + return JSONValue([ + "tps" : JSONValue(this.TicksPerSecond), + "functions" : JSONValue(ret)]); } -} -@("Function is alrighty") -unittest { - Function("_Dmain", 1).hashOf; -} + @safe pure nothrow const float timeOf(HASH f) + in { + assert(f in this.Functions); + } body { + return cast(float) this.Functions[f].Time / + cast(float) this.TicksPerSecond; + } -alias FuncMap = RefCounted!(HashMap!(HASH, Function)); + @safe pure nothrow const float percOf(HASH f) + in { + assert(f in this.Functions); + } body { + return (cast(float) this.Functions[f].Time / + cast(float) this.TicksPerSecond) / TimeOfMain * 100; + } -struct Entity { - private { - Function m_function; - FuncMap m_callsTo; - FuncMap m_calledBy; - ulong m_time; - ulong m_total_time; + @safe pure nothrow const float functionTimeOf(HASH f) + in { + assert(f in this.Functions); + } body { + return cast(float) this.Functions[f].FunctionTime / + cast(float) this.TicksPerSecond; } - alias m_function this; + @safe pure nothrow const float functionPercOf(HASH f) + in { + assert(f in this.Functions); + } body { + return (cast(float) this.Functions[f].FunctionTime / + cast(float) this.TicksPerSecond) / TimeOfMain * 100; + } -@property: - auto callsTo() { return m_callsTo; } - void callsTo(typeof(m_callsTo) t) { m_callsTo = t; } - void callsTo(Function f) - in(f.hashOf !in m_callsTo) { - m_callsTo[f.hashOf] = f; + const void writeDOT(ref File f, + in float threshold = 0, + in string[float] colours = [ + 0: "limegreen", + 10: "slateblue", + 25: "steelblue", + 50: "royalblue", + 75: "navy", + 95: "red" + ] + ) { + import std.string : tr, wrap; + import std.digest.crc : crc32Of; + + auto clr = (float f) { + import std.algorithm : sort; + foreach(k; sort!("a>b")(colours.keys)) + if(k <= f) + return colours[k]; + return "gray"; + }; + + HASH[][HASH] func; + enum fmt = "\"%s\" [label=\"%s\\n%.2f%%(%.2f%%)\", shape=\"box\"," ~ + " style=filled, fillcolor=\"%s\"];"; + + foreach(k, ref v; this.Functions) { + if(threshold == 0 || this.percOf(k) > threshold) { + func[k] = []; + foreach(key, unused; v.CallsTo) { + if(threshold != 0 && this.percOf(key) <= threshold) + continue; + if(key !in func) + func[key] = []; + func[k] ~= key; + } + } else { + continue; + } + } + + f.writeln("digraph {"); + foreach(k, ref v; func) { + f.writefln(fmt, + this.Functions[k].Mangled.tr("\"", "\\\""), + this.Functions[k].Name.tr("\"", "\\\"").wrap(40), + this.percOf(k), + this.functionPercOf(k), + clr(this.percOf(k))); + foreach(i; v) { + if(i !in func) { + f.writefln(fmt, + this.Functions[i].Mangled.tr("\"", "\\\""), + this.Functions[i].Name.tr("\"", "\\\"").wrap(40), + this.percOf(i), + this.functionPercOf(i), + clr(this.percOf(i))); + } + f.writefln("\"%s\" -> \"%s\" [label=\"%dx\"];", + this.Functions[k].Mangled.tr("\"", "\\\""), + this.Functions[i].Mangled.tr("\"", "\\\""), + this.Functions[k].CallsTo[i].Calls); + } + } + f.writeln("}"); } - auto calledBy() { return m_calledBy; } - void calledBy(typeof(m_callsTo) t) { m_calledBy = t; } - void calledBy(Function f) - in(f.hashOf !in m_calledBy) { - m_calledBy[f.hashOf] = f; + deprecated const void toDOT(scope void delegate(const(char)[]) s, + float threshold = 0, + string[float] colours = [ + 0: "limegreen", + 10: "slateblue", + 25: "steelblue", + 50: "royalblue", + 75: "navy", + 95: "red" + ] + ) { + import std.format : format; + import std.string : tr, wrap; + import std.digest.crc : crc32Of; + + string clr(float f) { + import std.algorithm : sort; + foreach(k; sort!("a>b")(colours.keys)) { + if(k <= f) { + return colours[k]; + } + } + return "gray"; + } + + HASH[][HASH] func; + enum fmt = "\"%s\" [label=\"%s\\n%.2f%%(%.2f%%)\", shape=\"box\"," ~ + " style=filled, fillcolor=\"%s\"];\n"; + + foreach(k, ref v; this.Functions) { + if(threshold == 0 || this.percOf(k) > threshold) { + func[k] = []; + foreach(key, unused; v.CallsTo) { + if(threshold != 0 && this.percOf(key) <= threshold) + continue; + if(key !in func) + func[key] = []; + func[k] ~= key; + } + } else { + continue; + } + } + + s("digraph {\n"); + foreach(k, ref v; func) { + s(fmt.format( + this.Functions[k].Mangled.tr("\"", "\\\""), + this.Functions[k].Name.tr("\"", "\\\"").wrap(40), + this.percOf(k), + this.functionPercOf(k), + clr(this.percOf(k)))); + foreach(i; v) { + if(i !in func) { + s(fmt.format( + this.Functions[i].Mangled.tr("\"", "\\\""), + this.Functions[i].Name.tr("\"", "\\\"").wrap(40), + this.percOf(i), + this.functionPercOf(i), + clr(this.percOf(i)))); + } + s("\"%s\" -> \"%s\" [label=\"%dx\"];\n".format( + this.Functions[k].Mangled.tr("\"", "\\\""), + this.Functions[i].Mangled.tr("\"", "\\\""), + this.Functions[k].CallsTo[i].Calls)); + } + } + s("}\n"); } +} + +private struct FunctionElement { + char[] Name; + char[] Mangled; + ulong Calls; +} - auto time() { return m_time; } - void time(ulong t) { m_time = t; } +private struct Function { + char[] Name; + char[] Mangled; + ulong Calls; + FunctionElement[HASH] CallsTo; + FunctionElement[HASH] CalledBy; + ulong FunctionTime; + ulong Time; - auto totalTime() { return m_total_time; } - void totalTime(ulong t) { m_total_time = t; } + void callsTo(FunctionElement func) { + import std.digest.crc : crc32Of; + HASH h = func.Mangled.crc32Of; + this.CallsTo[h] = func; + } + + void calledBy(FunctionElement func) { + import std.digest.crc : crc32Of; + HASH h = func.Mangled.crc32Of; + this.CalledBy[h] = func; + } }