From 589d8385c6b981e850dab6871f2a00760aff698a Mon Sep 17 00:00:00 2001 From: Jakob Botsch Nielsen Date: Tue, 16 Jul 2019 13:09:02 -0700 Subject: [PATCH] Log jit decisions in PMI This adds two flags that allows PMI to output inlining and tail-call decisions to stdout. --- build.cmd | 2 +- build.sh | 2 +- jitutils.sln | 15 ++ src/jit-decisions-analyze/README.md | 1 + .../jit-decisions-analyze.cs | 152 ++++++++++++++++++ .../jit-decisions-analyze.csproj | 14 ++ src/pmi/JITDecisionEventListener.cs | 41 +++++ src/pmi/pmi.cs | 17 ++ 8 files changed, 242 insertions(+), 2 deletions(-) create mode 100644 src/jit-decisions-analyze/README.md create mode 100644 src/jit-decisions-analyze/jit-decisions-analyze.cs create mode 100644 src/jit-decisions-analyze/jit-decisions-analyze.csproj create mode 100644 src/pmi/JITDecisionEventListener.cs diff --git a/build.cmd b/build.cmd index 2719fa54..23b79c16 100644 --- a/build.cmd +++ b/build.cmd @@ -49,7 +49,7 @@ goto :argLoop :build REM Declare the list of projects -set projects=jit-diff jit-dasm jit-analyze jit-format cijobs pmi jit-dasm-pmi +set projects=jit-diff jit-dasm jit-analyze jit-format cijobs pmi jit-dasm-pmi jit-decisions-analyze REM Build each project for %%p in (%projects%) do ( diff --git a/build.sh b/build.sh index 33963040..b580e5c1 100755 --- a/build.sh +++ b/build.sh @@ -51,7 +51,7 @@ while getopts "hpfbt:" opt; do done # declare the array of projects -declare -a projects=(jit-dasm jit-diff jit-analyze jit-format cijobs pmi jit-dasm-pmi) +declare -a projects=(jit-dasm jit-diff jit-analyze jit-format cijobs pmi jit-dasm-pmi jit-decisions-analyze) # for each project either build or publish for proj in "${projects[@]}" diff --git a/jitutils.sln b/jitutils.sln index 5586e502..d78cae1b 100644 --- a/jitutils.sln +++ b/jitutils.sln @@ -21,6 +21,8 @@ Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "pmi", "src\pmi\pmi.csproj", EndProject Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "jit-dasm-pmi", "src\jit-dasm-pmi\jit-dasm-pmi.csproj", "{2C846294-79D4-40EA-8ED3-0F01E033BE32}" EndProject +Project("{9A19103F-16F7-4668-BE54-9A1E7A4F7556}") = "jit-decisions-analyze", "src\jit-decisions-analyze\jit-decisions-analyze.csproj", "{59FB3663-C16C-4C3B-90A7-AF7259C8A39B}" +EndProject Global GlobalSection(SolutionConfigurationPlatforms) = preSolution Debug|Any CPU = Debug|Any CPU @@ -130,6 +132,18 @@ Global {2C846294-79D4-40EA-8ED3-0F01E033BE32}.Release|x64.Build.0 = Release|Any CPU {2C846294-79D4-40EA-8ED3-0F01E033BE32}.Release|x86.ActiveCfg = Release|Any CPU {2C846294-79D4-40EA-8ED3-0F01E033BE32}.Release|x86.Build.0 = Release|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Debug|Any CPU.ActiveCfg = Debug|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Debug|Any CPU.Build.0 = Debug|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Debug|x64.ActiveCfg = Debug|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Debug|x64.Build.0 = Debug|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Debug|x86.ActiveCfg = Debug|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Debug|x86.Build.0 = Debug|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Release|Any CPU.ActiveCfg = Release|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Release|Any CPU.Build.0 = Release|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Release|x64.ActiveCfg = Release|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Release|x64.Build.0 = Release|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Release|x86.ActiveCfg = Release|Any CPU + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B}.Release|x86.Build.0 = Release|Any CPU EndGlobalSection GlobalSection(NestedProjects) = preSolution {5B781D3D-308C-4415-8C68-17D557B143B8} = {69D45FDC-948D-464B-BF14-5675F291FC62} @@ -140,5 +154,6 @@ Global {19436C6B-39C9-4A88-8021-3242D098637E} = {69D45FDC-948D-464B-BF14-5675F291FC62} {829E459B-EE3D-46A9-AD4D-4F2B03D5188C} = {69D45FDC-948D-464B-BF14-5675F291FC62} {2C846294-79D4-40EA-8ED3-0F01E033BE32} = {69D45FDC-948D-464B-BF14-5675F291FC62} + {59FB3663-C16C-4C3B-90A7-AF7259C8A39B} = {69D45FDC-948D-464B-BF14-5675F291FC62} EndGlobalSection EndGlobal diff --git a/src/jit-decisions-analyze/README.md b/src/jit-decisions-analyze/README.md new file mode 100644 index 00000000..4cbda186 --- /dev/null +++ b/src/jit-decisions-analyze/README.md @@ -0,0 +1 @@ +# jit-decisions-analyze - Managed JIT decisions analysis tool diff --git a/src/jit-decisions-analyze/jit-decisions-analyze.cs b/src/jit-decisions-analyze/jit-decisions-analyze.cs new file mode 100644 index 00000000..b2122939 --- /dev/null +++ b/src/jit-decisions-analyze/jit-decisions-analyze.cs @@ -0,0 +1,152 @@ +using System; +using System.Collections.Generic; +using System.IO; +using System.Linq; + +namespace jit_decisions_analyze +{ + internal class Program + { + private static void Main(string[] args) + { + List events = new List(); + int malformed = 0; + static void WriteProgress(double pct) + { + Console.CursorLeft = 0; + Console.Write("{0:F2}% done", pct); + } + + using (var sr = new StreamReader(File.OpenRead(args[0]))) + { + int lines = 0; + string line; + while ((line = sr.ReadLine()) != null) + { + if (!line.StartsWith("JITTracing: ")) + continue; + + line = line.Substring("JITTracing: ".Length); + Event evt = ToEvent(line); + if (evt != null) + events.Add(evt); + else + malformed++; + + if (lines++ % 10000 == 0) + WriteProgress(sr.BaseStream.Position / (double)sr.BaseStream.Length * 100); + } + } + + WriteProgress(100); + Console.WriteLine(); + + Console.WriteLine("{0} total well-formed events ({1} filtered away because they were malformed)", events.Count, malformed); + List tailCalls = events.OfType().ToList(); + WriteInfo("Implicit", tailCalls.Where(t => !t.TailPrefix)); + WriteInfo("Explicit", tailCalls.Where(t => t.TailPrefix)); + WriteInfo("Inlining", events.OfType()); + } + + private static Event ToEvent(string l) + { + string[] data = l.Split("@!@!@"); + if (data.Length % 2 == 0) + return null; + + Dictionary payload = new Dictionary(); + for (int i = 1; i < data.Length; i += 2) + payload.Add(data[i], data[i + 1]); + + string tailPrefix; + string failReason; + switch (data[0]) + { + case "MethodJitTailCallSucceeded": + tailPrefix = payload.GetValueOrDefault("TailPrefix"); + if (tailPrefix == null) + return null; + + return new TailCallSucceededEvent { TailPrefix = tailPrefix == "True" }; + case "MethodJitTailCallFailed": + tailPrefix = payload.GetValueOrDefault("TailPrefix"); + failReason = payload.GetValueOrDefault("FailReason"); + if (failReason == null || tailPrefix == null) + return null; + + return new TailCallFailedEvent { FailReason = failReason, TailPrefix = tailPrefix == "True" }; + case "MethodJitInliningSucceeded": + return new InliningSucceededEvent(); + case "MethodJitInliningFailed": + failReason = payload.GetValueOrDefault("FailReason"); + if (failReason == null) + return null; + + return new InliningFailedEvent { FailReason = failReason }; + default: + return null; + } + } + + private static void WriteInfo(string name, IEnumerable events) + { + List list = events.ToList(); + int sites = list.Count; + int sitesSuccessful = list.Count(IsSuccessEvent); + Console.WriteLine("{0} call sites: {1}/{2} converted", name, sitesSuccessful, sites); + if (sites == 0) + return; + + string GetInfoString(Event e) + { + switch (e) + { + case TailCallSucceededEvent f: return "Successfully converted"; + case InliningSucceededEvent f: return "Successfully converted"; + case TailCallFailedEvent f: return f.FailReason; + case InliningFailedEvent f: return f.FailReason; + default: throw new ArgumentException("No fail reason on event"); + } + } + + var groupedFailures = list.GroupBy(GetInfoString).OrderByDescending(g => g.Count()); + foreach (var g in groupedFailures) + Console.WriteLine("[{0:00.00}%] {1}", g.Count() / (double)sites * 100, g.Key); + + Console.WriteLine(); + } + + private static bool IsSuccessEvent(Event e) => e is TailCallSucceededEvent || e is InliningSucceededEvent; + } + + internal abstract class Event + { + } + + internal abstract class TailCallEvent : Event + { + public bool TailPrefix { get; set; } + } + + internal class TailCallSucceededEvent : TailCallEvent + { + } + + internal class TailCallFailedEvent : TailCallEvent + { + public string FailReason { get; set; } + } + + internal abstract class InliningEvent : Event + { + } + + internal class InliningSucceededEvent : InliningEvent + { + } + + internal class InliningFailedEvent : InliningEvent + { + public string FailReason { get; set; } + } +} diff --git a/src/jit-decisions-analyze/jit-decisions-analyze.csproj b/src/jit-decisions-analyze/jit-decisions-analyze.csproj new file mode 100644 index 00000000..036eb0f1 --- /dev/null +++ b/src/jit-decisions-analyze/jit-decisions-analyze.csproj @@ -0,0 +1,14 @@ + + + + + + + Exe + + + + + + + diff --git a/src/pmi/JITDecisionEventListener.cs b/src/pmi/JITDecisionEventListener.cs new file mode 100644 index 00000000..281f31a8 --- /dev/null +++ b/src/pmi/JITDecisionEventListener.cs @@ -0,0 +1,41 @@ +using System; +using System.Collections.Generic; +using System.Diagnostics.Tracing; + +namespace pmi +{ + internal class JITDecisionEventListener : EventListener + { + // We cannot use a parameter to this event listener because + // EventListener constructor calls OnEventWritten, which will happen + // before we have been able to run our own constructor. + internal static readonly HashSet s_enabledEvents = new HashSet(); + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name != "Microsoft-Windows-DotNETRuntime") + return; + + EventKeywords jitTracing = (EventKeywords)0x1000; // JITTracing + EnableEvents(eventSource, EventLevel.Verbose, jitTracing); + } + + protected override void OnEventWritten(EventWrittenEventArgs data) + { + if (!s_enabledEvents.Contains(data.EventName)) + return; + + List dataStrings = new List { data.EventName }; + + for (int i = 0; i < data.Payload.Count; i++) + { + dataStrings.Add(data.PayloadNames[i]); + dataStrings.Add(data.Payload[i] != null ? data.Payload[i].ToString() : ""); + } + + // Log payload separated by @!@!@. This is somewhat ugly, but easy enough to parse + // and avoids pulling in a dependency here. + Console.WriteLine("JITTracing: {0}", string.Join("@!@!@", dataStrings)); + } + } +} diff --git a/src/pmi/pmi.cs b/src/pmi/pmi.cs index 51e3c2e6..b683a11a 100644 --- a/src/pmi/pmi.cs +++ b/src/pmi/pmi.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using pmi; using System; using System.Collections.Generic; using System.IO; @@ -1411,6 +1412,22 @@ public static int Main(string[] args) } bool runCctors = command.IndexOf("CCTORS") > 0; + bool logTailCallDecisions = command.IndexOf("TAILCALLS") > 0; + bool logInliningDecisions = command.IndexOf("INLINES") > 0; + + if (logTailCallDecisions) + { + JITDecisionEventListener.s_enabledEvents.Add("MethodJitTailCallSucceeded"); + JITDecisionEventListener.s_enabledEvents.Add("MethodJitTailCallFailed"); + } + if (logInliningDecisions) + { + JITDecisionEventListener.s_enabledEvents.Add("MethodJitInliningSucceeded"); + JITDecisionEventListener.s_enabledEvents.Add("MethodJitInliningFailed"); + } + + using var eventListener = + logTailCallDecisions || logInliningDecisions ? new JITDecisionEventListener() : null; Worker w = new Worker(v, runCctors); int result = 0;