diff --git a/build-tools/scripts/TimingDefinitions.txt b/build-tools/scripts/TimingDefinitions.txt new file mode 100644 index 00000000000..c0146ffeafe --- /dev/null +++ b/build-tools/scripts/TimingDefinitions.txt @@ -0,0 +1,6 @@ +# measure time of last monodroid-timing message appearance +last=monodroid-timing:\s+(?.*)$ + +# measure time of runtime and JNIEnv initialization end +init=monodroid-timing:\s+(?Runtime\.init: end native-to-managed.*)$ +JNI.init=monodroid-timing:\s+(?JNIEnv\.Initialize end:.*)$ diff --git a/build-tools/scripts/UnitTestApks.targets b/build-tools/scripts/UnitTestApks.targets index 9e606422a5c..75552569e91 100644 --- a/build-tools/scripts/UnitTestApks.targets +++ b/build-tools/scripts/UnitTestApks.targets @@ -146,6 +146,10 @@ - + + <_DefinitionsFilename Condition=" '%(UnitTestApk.TimingDefinitionsFilename)' == '' ">$(MSBuildThisFileDirectory)/TimingDefinitions.txt + <_DefinitionsFilename Condition=" '%(UnitTestApk.TimingDefinitionsFilename)' != '' ">%(UnitTestApk.TimingDefinitionsFilename) + + diff --git a/build-tools/xa-prep-tasks/Xamarin.Android.BuildTools.PrepTasks/ProcessLogcatTiming.cs b/build-tools/xa-prep-tasks/Xamarin.Android.BuildTools.PrepTasks/ProcessLogcatTiming.cs index af5713697cc..1f1f5e2f036 100644 --- a/build-tools/xa-prep-tasks/Xamarin.Android.BuildTools.PrepTasks/ProcessLogcatTiming.cs +++ b/build-tools/xa-prep-tasks/Xamarin.Android.BuildTools.PrepTasks/ProcessLogcatTiming.cs @@ -16,19 +16,51 @@ public class ProcessLogcatTiming : Task [Required] public string ApplicationPackageName { get; set; } + [Required] + public string DefinitionsFilename { get; set; } + public string ResultsFilename { get; set; } + Dictionary definedRegexs = new Dictionary (); + Dictionary results = new Dictionary (); + + void LoadDefinitions () + { + using (var reader = new StreamReader (DefinitionsFilename)) { + string line; + + while ((line = reader.ReadLine ()) != null) { + if (line.StartsWith ("#", StringComparison.Ordinal)) + continue; + int index = line.IndexOf ('='); + if (index < 1 || index == line.Length) + continue; + var label = line.Substring (0, index); + var pattern = line.Substring (index + 1); + Regex regex; + try { + regex = new Regex (pattern); + } catch (Exception e) { + Log.LogWarning ($"unable to create regex for label: {label} from pattern: {pattern}\n{e}"); + continue; + } + if (definedRegexs.ContainsKey (label)) + Log.LogWarning ($"label '{label}' is defined multiple times. the last definition will be used"); + definedRegexs [label] = regex; + } + } + } + public override bool Execute () { + LoadDefinitions (); using (var reader = new StreamReader (LogcatFilename)) { string line; int pid = -1; var procStartRegex = new Regex ($@"^(?\d+-\d+\s+[\d:\.]+)\s+.*ActivityManager: Start proc.*for added application {ApplicationPackageName}: pid=(?\d+)"); Regex timingRegex = null; - var runtimeInitRegex = new Regex (@"Runtime\.init: end native-to-managed"); DateTime start = DateTime.Now; DateTime last = start; - DateTime initEnd = start; while ((line = reader.ReadLine ()) != null) { if (pid == -1) { @@ -39,7 +71,7 @@ public override bool Execute () last = start = ParseTime (match.Groups ["timestamp"].Value); pid = Int32.Parse (match.Groups ["pid"].Value); Log.LogMessage (MessageImportance.Low, $"Time: 0ms process start, application: '{ApplicationPackageName}' PID: {pid}"); - timingRegex = new Regex ($@"^(?\d+-\d+\s+[\d:\.]+)\s+{pid}\s+.*I monodroid-timing:\s(?.*)$"); + timingRegex = new Regex ($@"^(?\d+-\d+\s+[\d:\.]+)\s+{pid}\s+(?.*)$"); } else { var match = timingRegex.Match (line); if (!match.Success) @@ -47,23 +79,36 @@ public override bool Execute () var time = ParseTime (match.Groups ["timestamp"].Value); var span = time - start; - Log.LogMessage (MessageImportance.Low, $"Time: {span.TotalMilliseconds.ToString ().PadLeft (6)}ms Message: {match.Groups ["message"].Value}"); - match = runtimeInitRegex.Match (match.Groups ["message"].Value); - if (match.Success) - initEnd = time; - last = time; + string message = match.Groups ["message"].Value; + string logMessage = message; + + foreach (var regex in definedRegexs) { + var definedMatch = regex.Value.Match (message); + if (!definedMatch.Success) + continue; + results [regex.Key] = span.TotalMilliseconds.ToString (); + var m = definedMatch.Groups ["message"]; + if (m.Success) + logMessage = m.Value; + + Log.LogMessage (MessageImportance.Low, $"Time: {span.TotalMilliseconds.ToString ().PadLeft (6)}ms Message: {logMessage}"); + last = time; + } } } if (pid != -1) { Log.LogMessage (MessageImportance.Normal, " -- Performance summary --"); - Log.LogMessage (MessageImportance.Normal, $"Runtime init end: {(initEnd - start).TotalMilliseconds}ms"); Log.LogMessage (MessageImportance.Normal, $"Last timing message: {(last - start).TotalMilliseconds}ms"); - if (ResultsFilename != null) - File.WriteAllText (Path.Combine (Path.GetDirectoryName (ResultsFilename), $"Test-{ApplicationPackageName}-times.csv"), - $"init,last\n{(initEnd - start).TotalMilliseconds},{(last - start).TotalMilliseconds}"); + if (ResultsFilename != null) { + using (var resultsFile = new StreamWriter (Path.Combine (Path.GetDirectoryName (ResultsFilename), $"Test-{ApplicationPackageName}-times.csv"))) { + WriteValues (resultsFile, results.Keys); + WriteValues (resultsFile, results.Values); + resultsFile.Close (); + } + } } else Log.LogWarning ("Wasn't able to collect the performance data"); @@ -73,6 +118,18 @@ public override bool Execute () return true; } + void WriteValues (StreamWriter writer, ICollection values) + { + bool first = true; + foreach (var key in values) { + if (!first) + writer.Write (','); + writer.Write (key); + first = false; + } + writer.WriteLine (); + } + static Regex timeRegex = new Regex (@"(?\d+)-(?\d+)\s+(?\d+):(?\d+):(?\d+)\.(?\d+)"); DateTime ParseTime (string s) { diff --git a/src/Mono.Android/Android.Runtime/JNIEnv.cs b/src/Mono.Android/Android.Runtime/JNIEnv.cs index 595194bfb31..87390f9db95 100644 --- a/src/Mono.Android/Android.Runtime/JNIEnv.cs +++ b/src/Mono.Android/Android.Runtime/JNIEnv.cs @@ -288,6 +288,11 @@ internal static unsafe void Initialize (JnienvInitializeArgs* args) if (!IsRunningOnDesktop) Java.Lang.Thread.DefaultUncaughtExceptionHandler = defaultUncaughtExceptionHandler; } + + if (Logger.LogTiming) + Logger.Log (LogLevel.Info, + "monodroid-timing", + "JNIEnv.Initialize end: " + (DateTime.UtcNow - new DateTime (1970, 1, 1)).TotalMilliseconds); } internal static void Exit ()