[jit-times] Add jit-times tool (#2801)

`jit-times` is a tool to process the `methods.txt` file produced by
Xamarin.Android applications:

	Usage: jit-times.exe OPTIONS* <methods-file>
	
	Processes JIT methods file from XA app with debug.mono.log=timing enabled
	
	Copyright 2019 Microsoft Corporation
	
	Options:
	  -h, --help, -?             Show this message and exit
	  -m, --method=TYPE-REGEX    Process only methods whose names match TYPE-REGEX.
	  -s                         Sort by self times. (this is default ordering)
	  -t                         Sort by total times.
	  -u                         Show unsorted results.
	  -v, --verbose              Output information about progress during the run
	                               of the tool

~~ Getting the `methods.txt` file ~~

The `methods.txt` file can be acquired from Xamarin.Android
application by:

 1. Set the `debug.mono.log` system property to include `timing`:

        adb shell setprop debug.mono.log timing`

 2. Run the application

 3. Grab `methods.txt`:

        adb shell run-as @PACKAGE_NAME@ cat files/.__override__/methods.txt > methods.txt

~~ Example usage ~~

To Ddsplay JIT times for `System.Reflection.Emit` methods

	mono jit-times.exe -m ^System.Reflection.Emit methods.txt

Results in:

```
Total (ms) |  Self (ms) | Method
      8.35 |       8.35 | System.Reflection.Emit.OpCodes:.cctor ()
      0.57 |       0.57 | System.Reflection.Emit.ILGenerator:Emit (System.Reflection.Emit.OpCode,System.Reflection.Emit.LocalBuilder)
      0.49 |       0.49 | System.Reflection.Emit.ILGenerator:Emit (System.Reflection.Emit.OpCode,System.Reflection.MethodInfo)
      0.39 |       0.39 | System.Reflection.Emit.DynamicMethod:.ctor (string,System.Reflection.MethodAttributes,System.Reflection.CallingConventions,System.Type,System.Type[],System.Type,System.Reflection.Module,bool,bool)
      0.36 |       0.36 | System.Reflection.Emit.ILGenerator:Emit (System.Reflection.Emit.OpCode,System.Reflection.Emit.Label)
      0.36 |       0.36 | System.Reflection.Emit.ILGenerator:DeclareLocal (System.Type,bool)
      0.35 |       0.35 | System.Reflection.Emit.ILGenerator:BeginExceptionBlock ()
      0.34 |       0.34 | System.Reflection.Emit.ILGenerator:Emit (System.Reflection.Emit.OpCode,System.Type)
      0.31 |       0.31 | System.Reflection.Emit.DynamicMethod:CreateDynMethod ()
      0.29 |       0.29 | System.Reflection.Emit.ILGenerator:DefineLabel ()
      0.27 |       0.27 | System.Reflection.Emit.ILGenerator:BeginCatchBlock (System.Type)
      ...
Sum of self time (ms): 16.02
```
This commit is contained in:
Radek Doulik 2019-03-08 16:12:01 +01:00 коммит произвёл Jonathan Pryor
Родитель 6bb8533780
Коммит f74cd443ae
10 изменённых файлов: 552 добавлений и 0 удалений

Просмотреть файл

@ -127,6 +127,8 @@ Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "proprietary", "build-tools\
EndProject
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "download-bundle", "build-tools\download-bundle\download-bundle.csproj", "{1DA0CB12-5508-4E83-A242-0C8D6D99A49B}"
EndProject
Project("{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC}") = "jit-times", "tools\jit-times\jit-times.csproj", "{F3CFF31C-037B-450F-B22D-1D6E529B2DCC}"
EndProject
Global
GlobalSection(SharedMSBuildProjectFiles) = preSolution
src\Xamarin.Android.NamingCustomAttributes\Xamarin.Android.NamingCustomAttributes.projitems*{3f1f2f50-af1a-4a5a-bedb-193372f068d7}*SharedItemsImports = 4
@ -365,6 +367,10 @@ Global
{1DA0CB12-5508-4E83-A242-0C8D6D99A49B}.Debug|AnyCPU.Build.0 = Debug|Any CPU
{1DA0CB12-5508-4E83-A242-0C8D6D99A49B}.Release|AnyCPU.ActiveCfg = Release|Any CPU
{1DA0CB12-5508-4E83-A242-0C8D6D99A49B}.Release|AnyCPU.Build.0 = Release|Any CPU
{F3CFF31C-037B-450F-B22D-1D6E529B2DCC}.Debug|AnyCPU.ActiveCfg = Debug|Any CPU
{F3CFF31C-037B-450F-B22D-1D6E529B2DCC}.Debug|AnyCPU.Build.0 = Debug|Any CPU
{F3CFF31C-037B-450F-B22D-1D6E529B2DCC}.Release|AnyCPU.ActiveCfg = Release|Any CPU
{F3CFF31C-037B-450F-B22D-1D6E529B2DCC}.Release|AnyCPU.Build.0 = Release|Any CPU
EndGlobalSection
GlobalSection(SolutionProperties) = preSolution
HideSolutionNode = FALSE
@ -425,6 +431,7 @@ Global
{E34BCFA0-CAA4-412C-AA1C-75DB8D67D157} = {04E3E11E-B47D-4599-8AFC-50515A95E715}
{1E5501E8-49C1-4659-838D-CC9720C5208F} = {CAB438D8-B0F5-4AF0-BEBD-9E2ADBD7B483}
{1BAFA0CC-0377-46CE-AB7B-7BB2E7B62F63} = {04E3E11E-B47D-4599-8AFC-50515A95E715}
{F3CFF31C-037B-450F-B22D-1D6E529B2DCC} = {864062D3-A415-4A6F-9324-5820237BA058}
EndGlobalSection
GlobalSection(ExtensibilityGlobals) = postSolution
SolutionGuid = {53A1F287-EFB2-4D97-A4BB-4A5E145613F6}

Просмотреть файл

@ -196,6 +196,7 @@
<ItemGroup>
<_MonoScript Include="mono-symbolicate" />
<_MonoScript Include="illinkanalyzer" />
<_MonoScript Include="jit-times" />
<_MonoScriptSource Include="@(_MonoScript->'$(_MonoScriptSourceDirectory)\%(Identity)')" />
<_MonoScriptDestination Include="@(_MonoScript->'$(_MonoScriptDestinationDirectory)\%(Identity)')" />
</ItemGroup>

Просмотреть файл

@ -0,0 +1,41 @@
using System.Collections.Generic;
namespace jittimes {
public class MethodInfo {
public enum State {
None,
Begin,
Done,
};
public string method;
public State state;
public Timestamp begin, done;
public Timestamp total, self;
public List<MethodInfo> inner;
public void AddInner (MethodInfo info)
{
if (inner == null)
inner = new List<MethodInfo> ();
inner.Add (info);
}
public bool CalcSelfTime ()
{
self = total;
if (inner == null)
return false;
foreach (var im in inner)
self -= im.total;
return true;
}
}
}

250
tools/jit-times/Program.cs Normal file
Просмотреть файл

@ -0,0 +1,250 @@
using Mono.Options;
using System;
using System.Collections.Generic;
using System.IO;
using System.Linq;
using System.Text.RegularExpressions;
using static System.Console;
namespace jittimes {
class MainClass {
static bool Verbose;
static readonly string Name = "jit-times";
static readonly List<Regex> methodNameRegexes = new List<Regex> ();
enum SortKind {
Unsorted,
Self,
Total,
};
static SortKind sortKind = SortKind.Self;
static string ProcessArguments (string [] args)
{
var help = false;
var options = new OptionSet {
$"Usage: {Name}.exe OPTIONS* <methods-file>",
"",
"Processes JIT methods file from XA app with debug.mono.log=timing enabled",
"",
"Copyright 2019 Microsoft Corporation",
"",
"Options:",
{ "h|help|?",
"Show this message and exit",
v => help = v != null },
{ "m|method=",
"Process only methods whose names match {TYPE-REGEX}.",
v => methodNameRegexes.Add (new Regex (v)) },
{ "s",
"Sort by self times. (this is default ordering)",
v => sortKind = SortKind.Self },
{ "t",
"Sort by total times.",
v => sortKind = SortKind.Total },
{ "u",
"Show unsorted results.",
v => sortKind = SortKind.Unsorted },
{ "v|verbose",
"Output information about progress during the run of the tool",
v => Verbose = true },
};
var remaining = options.Parse (args);
if (help || args.Length < 1) {
options.WriteOptionDescriptions (Out);
Environment.Exit (0);
}
if (remaining.Count != 1) {
Error ("Please specify one <methods-file> to process.");
Environment.Exit (2);
}
return remaining [0];
}
static bool TryMatchTimeStamp (Regex regex, string line, out string method, out Timestamp time)
{
var match = regex.Match (line);
if (!match.Success || match.Groups.Count <= 2) {
method = null;
time = new Timestamp ();
return false;
}
method = match.Groups [1].Value;
time = Timestamp.Parse (match.Groups [2].Value);
return true;
}
static readonly Dictionary<string, MethodInfo> methods = new Dictionary<string, MethodInfo> ();
static bool ShouldPrint (string method)
{
if (methodNameRegexes.Count > 0) {
var success = false;
foreach (var filter in methodNameRegexes) {
var match = filter.Match (method);
success |= match.Success;
}
return success;
}
return true;
}
static void PrintIndented (MethodInfo info, ref Timestamp sum, int level = 0)
{
if (!ShouldPrint (info.method))
return;
sum += info.self;
WriteLine ($"{info.total.Milliseconds (),10:F2} | {info.self.Milliseconds (),10:F2} | {"".PadRight (level * 2)}{info.method}");
if (info.inner == null)
return;
foreach (var im in info.inner)
PrintIndented (im, ref sum, level + 1);
}
static MethodInfo GetMethodInfo (string method)
{
MethodInfo info;
if (methods.TryGetValue (method, out info))
return info;
info = new MethodInfo { method = method };
methods [method] = info;
return info;
}
public static int Main (string [] args)
{
var path = ProcessArguments (args);
var file = File.OpenText (path);
var beginRegex = new Regex (@"^JIT method +begin: (.*) elapsed: (.*)$");
var doneRegex = new Regex (@"^JIT method +done: (.*) elapsed: (.*)$");
string line;
int lineNumber = 0;
var jitMethods = new Stack<MethodInfo> ();
string method;
Timestamp time;
Timestamp sum = new Timestamp ();
ColorWriteLine ("Total (ms) | Self (ms) | Method", ConsoleColor.Yellow);
while ((line = file.ReadLine ()) != null) {
lineNumber++;
if (TryMatchTimeStamp (beginRegex, line, out method, out time)) {
var info = GetMethodInfo (method);
if (info.state != MethodInfo.State.None && Verbose)
Warning ($"duplicit begin of `{info.method}`");
info.state = MethodInfo.State.Begin;
info.begin = time;
jitMethods.Push (info);
continue;
}
if (TryMatchTimeStamp (doneRegex, line, out method, out time)) {
var info = GetMethodInfo (method);
if (info.state != MethodInfo.State.Begin) {
if (Verbose)
Warning ($"missing JIT begin for method {method}");
continue;
}
info.state = MethodInfo.State.Done;
info.done = time;
info.total = info.done - info.begin;
info.CalcSelfTime ();
jitMethods.Pop ();
if (jitMethods.Count > 0) {
var outerMethod = jitMethods.Peek ();
outerMethod.AddInner (info);
} else if (sortKind == SortKind.Unsorted)
PrintIndented (info, ref sum);
}
}
if (sortKind != SortKind.Unsorted)
sum = PrintSortedMethods ();
ColorWriteLine ($"Sum of self time (ms): {sum.Milliseconds ():F2}", ConsoleColor.Yellow);
return 0;
}
static Timestamp PrintSortedMethods ()
{
IOrderedEnumerable<KeyValuePair<string, MethodInfo>> enumerable = null;
Timestamp sum = new Timestamp ();
switch (sortKind) {
case SortKind.Self:
enumerable = methods.OrderByDescending (p => p.Value.self);
break;
case SortKind.Total:
enumerable = methods.OrderByDescending (p => p.Value.total);
break;
default:
throw new InvalidOperationException ("unknown sort order");
}
foreach (var pair in enumerable) {
if (!ShouldPrint (pair.Key))
continue;
var info = pair.Value;
WriteLine ($"{info.total.Milliseconds (),10:F2} | {info.self.Milliseconds (),10:F2} | {info.method}");
sum += info.self;
}
return sum;
}
static void ColorMessage (string message, ConsoleColor color, TextWriter writer, bool writeLine = true)
{
ForegroundColor = color;
if (writeLine)
writer.WriteLine (message);
else
writer.Write (message);
ResetColor ();
}
public static void ColorWriteLine (string message, ConsoleColor color) => ColorMessage (message, color, Out);
public static void ColorWrite (string message, ConsoleColor color) => ColorMessage (message, color, Out, false);
public static void Error (string message) => ColorMessage ($"Error: {Name}: {message}", ConsoleColor.Red, Console.Error);
public static void Warning (string message) => ColorMessage ($"Warning: {Name}: {message}", ConsoleColor.Yellow, Console.Error);
}
}

Просмотреть файл

@ -0,0 +1,25 @@
using System.Reflection;
// Information about this assembly is defined by the following attributes.
// Change them to the values specific to your project.
[assembly: AssemblyTitle ("jit-times")]
[assembly: AssemblyDescription ("")]
[assembly: AssemblyConfiguration ("")]
[assembly: AssemblyCompany ("Microsoft Corporation")]
[assembly: AssemblyProduct ("")]
[assembly: AssemblyCopyright ("2019 Microsoft Corporation")]
[assembly: AssemblyTrademark ("")]
[assembly: AssemblyCulture ("")]
// The assembly version has the format "{Major}.{Minor}.{Build}.{Revision}".
// The form "{Major}.{Minor}.*" will automatically update the build and revision,
// and "{Major}.{Minor}.{Build}.*" will update just the revision.
[assembly: AssemblyVersion ("1.0.*")]
// The following attributes are used to specify the signing key for the assembly,
// if desired. See the Mono documentation for more information about signing.
//[assembly: AssemblyDelaySign(false)]
//[assembly: AssemblyKeyFile("")]

56
tools/jit-times/README.md Normal file
Просмотреть файл

@ -0,0 +1,56 @@
**jit-times** is a tool to process methods.txt file produced by Xamarin.Android
applications
Usage: jit-times.exe OPTIONS* <methods-file>
Processes JIT methods file from XA app with debug.mono.log=timing enabled
Copyright 2019 Microsoft Corporation
Options:
-h, --help, -? Show this message and exit
-m, --method=TYPE-REGEX Process only methods whose names match TYPE-REGEX.
-s Sort by self times. (this is default ordering)
-t Sort by total times.
-u Show unsorted results.
-v, --verbose Output information about progress during the run
of the tool
### Getting the `methods.txt` file
The `methods.txt` file can be acquired from Xamarin.Android application like this:
1. Set the `debug.mono.log` system property to include `timing`:
adb shell setprop debug.mono.log timing`
2. Run the application
3. Grab `methods.txt`:
adb shell run-as @PACKAGE_NAME@ cat files/.__override__/methods.txt > methods.txt
### Example usage:
To display JIT times for `System.Reflection.Emit` methods
mono jit-times.exe -m ^System.Reflection.Emit methods.txt
Results in:
```
Total (ms) | Self (ms) | Method
8.35 | 8.35 | System.Reflection.Emit.OpCodes:.cctor ()
0.57 | 0.57 | System.Reflection.Emit.ILGenerator:Emit (System.Reflection.Emit.OpCode,System.Reflection.Emit.LocalBuilder)
0.49 | 0.49 | System.Reflection.Emit.ILGenerator:Emit (System.Reflection.Emit.OpCode,System.Reflection.MethodInfo)
0.39 | 0.39 | System.Reflection.Emit.DynamicMethod:.ctor (string,System.Reflection.MethodAttributes,System.Reflection.CallingConventions,System.Type,System.Type[],System.Type,System.Reflection.Module,bool,bool)
0.36 | 0.36 | System.Reflection.Emit.ILGenerator:Emit (System.Reflection.Emit.OpCode,System.Reflection.Emit.Label)
0.36 | 0.36 | System.Reflection.Emit.ILGenerator:DeclareLocal (System.Type,bool)
0.35 | 0.35 | System.Reflection.Emit.ILGenerator:BeginExceptionBlock ()
0.34 | 0.34 | System.Reflection.Emit.ILGenerator:Emit (System.Reflection.Emit.OpCode,System.Type)
0.31 | 0.31 | System.Reflection.Emit.DynamicMethod:CreateDynMethod ()
0.29 | 0.29 | System.Reflection.Emit.ILGenerator:DefineLabel ()
0.27 | 0.27 | System.Reflection.Emit.ILGenerator:BeginCatchBlock (System.Type)
...
Sum of self time (ms): 16.02
```

Просмотреть файл

@ -0,0 +1,113 @@
using System;
using System.Text.RegularExpressions;
namespace jittimes {
public struct Timestamp : IComparable {
public Int64 seconds;
public int milliseconds;
public int nanoseconds;
static readonly Regex regex = new Regex ("^([0-9]+)s:([0-9]+)::([0-9]+)$");
public static Timestamp Parse (string time)
{
Timestamp ts = new Timestamp ();
var match = regex.Match (time);
if (!match.Success || match.Groups.Count <= 3) {
ts.seconds = 0;
ts.milliseconds = 0;
ts.nanoseconds = 0;
return ts;
}
ts.seconds = Convert.ToInt64 (match.Groups [1].Value);
ts.milliseconds = Convert.ToInt32 (match.Groups [2].Value);
ts.nanoseconds = Convert.ToInt32 (match.Groups [3].Value);
return ts;
}
static public Timestamp operator - (Timestamp ts1, Timestamp ts2)
{
Timestamp result = new Timestamp ();
if (ts1.nanoseconds >= ts2.nanoseconds)
result.nanoseconds = ts1.nanoseconds - ts2.nanoseconds;
else {
result.nanoseconds = 1000000 + ts1.nanoseconds - ts2.nanoseconds;
result.milliseconds--;
}
if (ts1.milliseconds >= ts2.milliseconds)
result.milliseconds += ts1.milliseconds - ts2.milliseconds;
else {
result.milliseconds += 1000 + ts1.milliseconds - ts2.milliseconds;
result.seconds--;
}
result.seconds += ts1.seconds - ts2.seconds;
return result;
}
static public Timestamp operator + (Timestamp ts1, Timestamp ts2)
{
Timestamp result = new Timestamp {
nanoseconds = ts1.nanoseconds + ts2.nanoseconds
};
if (result.nanoseconds > 1000000) {
result.milliseconds += result.nanoseconds / 1000000;
result.nanoseconds %= 1000000;
}
result.milliseconds += ts1.milliseconds + ts2.milliseconds;
if (result.milliseconds > 1000) {
result.seconds += result.milliseconds / 1000;
result.milliseconds %= 1000;
}
return result;
}
public override string ToString ()
{
var sec = seconds != 0 ? $"{seconds}(s):" : "";
return $"{sec}{milliseconds}::{nanoseconds}";
}
public double Milliseconds ()
{
return seconds * 1000.0 + (double)milliseconds + nanoseconds / 1000000.0;
}
public int CompareTo (object o)
{
if (!(o is Timestamp other))
throw new ArgumentException ("Object is not a Timestamp");
if (seconds > other.seconds)
return 1;
if (seconds < other.seconds)
return -1;
if (milliseconds > other.milliseconds)
return 1;
if (milliseconds < other.milliseconds)
return -1;
if (nanoseconds > other.nanoseconds)
return 1;
if (nanoseconds < other.nanoseconds)
return -1;
return 0;
}
}
}

Просмотреть файл

@ -0,0 +1,49 @@
<?xml version="1.0" encoding="utf-8"?>
<Project DefaultTargets="Build" ToolsVersion="4.0" xmlns="http://schemas.microsoft.com/developer/msbuild/2003">
<PropertyGroup>
<Configuration Condition=" '$(Configuration)' == '' ">Debug</Configuration>
<Platform Condition=" '$(Platform)' == '' ">AnyCPU</Platform>
<ProjectGuid>{F3CFF31C-037B-450F-B22D-1D6E529B2DCC}</ProjectGuid>
<OutputType>Exe</OutputType>
<RootNamespace>jittimes</RootNamespace>
<AssemblyName>jit-times</AssemblyName>
<TargetFrameworkVersion>v4.7</TargetFrameworkVersion>
</PropertyGroup>
<PropertyGroup Condition=" '$(Configuration)|$(Platform)' == 'Debug|AnyCPU' ">
<DebugSymbols>true</DebugSymbols>
<DebugType>full</DebugType>
<Optimize>false</Optimize>
<OutputPath>$(XAInstallPrefix)xbuild\Xamarin\Android\</OutputPath>
<DefineConstants>DEBUG;</DefineConstants>
<ErrorReport>prompt</ErrorReport>
<WarningLevel>4</WarningLevel>
<ExternalConsole>true</ExternalConsole>
<PlatformTarget>AnyCPU</PlatformTarget>
</PropertyGroup>
<Import Project="..\..\Configuration.props" />
<PropertyGroup Condition=" '$(Configuration)|$(Platform)' == 'Release|AnyCPU' ">
<Optimize>true</Optimize>
<OutputPath>$(XAInstallPrefix)xbuild\Xamarin\Android\</OutputPath>
<ErrorReport>prompt</ErrorReport>
<WarningLevel>4</WarningLevel>
<ExternalConsole>true</ExternalConsole>
<PlatformTarget>AnyCPU</PlatformTarget>
</PropertyGroup>
<ItemGroup>
<Reference Include="System" />
<Reference Include="Mono.Options">
<HintPath>packages\Mono.Options.5.3.0.1\lib\net4-client\Mono.Options.dll</HintPath>
</Reference>
</ItemGroup>
<ItemGroup>
<Compile Include="Program.cs" />
<Compile Include="Properties\AssemblyInfo.cs" />
<Compile Include="Timestamp.cs" />
<Compile Include="MethodInfo.cs" />
</ItemGroup>
<ItemGroup>
<None Include="packages.config" />
<None Include="README.md" />
</ItemGroup>
<Import Project="$(MSBuildBinPath)\Microsoft.CSharp.targets" />
</Project>

Просмотреть файл

@ -0,0 +1,4 @@
<?xml version="1.0" encoding="utf-8"?>
<packages>
<package id="Mono.Options" version="5.3.0.1" targetFramework="net47" />
</packages>

6
tools/scripts/jit-times Executable file
Просмотреть файл

@ -0,0 +1,6 @@
#!/bin/sh
BINDIR=`dirname "$0"`
MANDROID_DIR="$BINDIR/.."
unset MONO_PATH
exec mono $MONO_OPTIONS "$MANDROID_DIR/jit-times.exe" "$@"