Skip to content

Commit df79d3d

Browse files
radekdoulikjonpryor
radekdoulik
authored and
jonpryor
committed
[tests] Process logcat output to measure startup times (#680)
- setup emulator with bigger logcat buffers, enable debug timing output - dump logcat to file after test is run and process it with the new task - the task also creates csv files with data to be used by Jenkins, plot plugin https://wiki.jenkins.io/display/JENKINS/Plot+Plugin the resulting plot can be seen here https://jenkins.mono-project.com/job/xamarin-android-pr-builder/plot/ the init value means time to get to the Runtime.init end, in milliseconds the last value means time to get to the last timing line (monodroid-timing) in the logcat ouput for the application, in milliseconds - the intent is to be aware about basic performance and to be able to detect performance regressions. it will be extended to measure more interesting times, like getting to the point where UI gets responsive in test app like out Hello world sample or Forms application sample - it produces 2 outputs. csv file for plot plugin (when requested), which is simple csv file with 2 lines, column names and column data. example: init,last 799,2935 second output uses the Log class, performance summary with normal priority and detailed output with low priority
1 parent 42ec1af commit df79d3d

File tree

3 files changed

+107
-0
lines changed

3 files changed

+107
-0
lines changed

‎build-tools/scripts/UnitTestApks.targets‎

Lines changed: 13 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@
77
<UsingTask AssemblyFile="$(MSBuildThisFileDirectory)..\..\bin\Build$(Configuration)\Xamarin.Android.Tools.BootstrapTasks.dll" TaskName="Xamarin.Android.Tools.BootstrapTasks.StartAndroidEmulator" />
88
<UsingTask AssemblyFile="$(MSBuildThisFileDirectory)..\..\bin\Build$(Configuration)\Xamarin.Android.Tools.BootstrapTasks.dll" TaskName="Xamarin.Android.Tools.BootstrapTasks.KillProcess" />
99
<UsingTask AssemblyFile="$(MSBuildThisFileDirectory)..\..\bin\Build$(Configuration)\xa-prep-tasks.dll" TaskName="Xamarin.Android.BuildTools.PrepTasks.Sleep" />
10+
<UsingTask AssemblyFile="$(MSBuildThisFileDirectory)..\..\bin\Build$(Configuration)\xa-prep-tasks.dll" TaskName="Xamarin.Android.BuildTools.PrepTasks.ProcessLogcatTiming" />
1011

1112
<PropertyGroup>
1213
<_TestImageName>XamarinAndroidUnitTestRunner</_TestImageName>
@@ -55,6 +56,16 @@
5556
Arguments="$(_EmuTarget) shell 'counter=0; while [ $counter -lt 60 ] &amp;&amp; [ &quot;`getprop sys.boot_completed`&quot; != &quot;1&quot; ]; do echo Waiting for device to fully boot; sleep 1; let &quot;counter++&quot;; done'"
5657
ToolExe="$(AdbToolExe)"
5758
ToolPath="$(AdbToolPath)"
59+
/>
60+
<Xamarin.Android.Tools.BootstrapTasks.Adb
61+
Arguments="$(_AdbTarget) shell setprop debug.mono.log timing"
62+
ToolExe="$(AdbToolExe)"
63+
ToolPath="$(AdbToolPath)"
64+
/>
65+
<Xamarin.Android.Tools.BootstrapTasks.Adb
66+
Arguments="$(_AdbTarget) logcat -G 4M"
67+
ToolExe="$(AdbToolExe)"
68+
ToolPath="$(AdbToolPath)"
5869
/>
5970
<Message
6071
Condition=" '$(_EmuTarget)' != '' "
@@ -134,5 +145,7 @@
134145
ToolPath="$(AdbToolPath)">
135146
<Output TaskParameter="FailedToRun" ItemName="_FailedComponent"/>
136147
</RunInstrumentationTests>
148+
<Exec Command="&quot;$(AdbToolPath)\$(AdbToolExe)&quot; $(_AdbTarget) $(AdbOptions) logcat -v threadtime -d > test-logcat.txt" />
149+
<ProcessLogcatTiming LogcatFilename="test-logcat.txt" ApplicationPackageName="%(UnitTestApk.Package)" ResultsFilename="%(UnitTestApk.ResultsPath)" />
137150
</Target>
138151
</Project>

‎build-tools/xa-prep-tasks/Xamarin.Android.BuildTools.PrepTasks/ProcessLogcatTiming.cs‎

Lines changed: 93 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,93 @@
1+
using System;
2+
using System.Collections.Generic;
3+
using System.IO;
4+
using System.Text.RegularExpressions;
5+
6+
using Microsoft.Build.Framework;
7+
using Microsoft.Build.Utilities;
8+
9+
namespace Xamarin.Android.BuildTools.PrepTasks
10+
{
11+
public class ProcessLogcatTiming : Task
12+
{
13+
[Required]
14+
public string LogcatFilename { get; set; }
15+
16+
[Required]
17+
public string ApplicationPackageName { get; set; }
18+
19+
public string ResultsFilename { get; set; }
20+
21+
public override bool Execute ()
22+
{
23+
using (var reader = new StreamReader (LogcatFilename)) {
24+
string line;
25+
int pid = -1;
26+
var procStartRegex = new Regex ($@"^(?<timestamp>\d+-\d+\s+[\d:\.]+)\s+.*ActivityManager: Start proc.*for added application {ApplicationPackageName}: pid=(?<pid>\d+)");
27+
Regex timingRegex = null;
28+
var runtimeInitRegex = new Regex (@"Runtime\.init: end native-to-managed");
29+
DateTime start = DateTime.Now;
30+
DateTime last = start;
31+
DateTime initEnd = start;
32+
33+
while ((line = reader.ReadLine ()) != null) {
34+
if (pid == -1) {
35+
var match = procStartRegex.Match (line);
36+
if (!match.Success)
37+
continue;
38+
39+
last = start = ParseTime (match.Groups ["timestamp"].Value);
40+
pid = Int32.Parse (match.Groups ["pid"].Value);
41+
Log.LogMessage (MessageImportance.Low, $"Time: 0ms process start, application: '{ApplicationPackageName}' PID: {pid}");
42+
timingRegex = new Regex ($@"^(?<timestamp>\d+-\d+\s+[\d:\.]+)\s+{pid}\s+.*I monodroid-timing:\s(?<message>.*)$");
43+
} else {
44+
var match = timingRegex.Match (line);
45+
if (!match.Success)
46+
continue;
47+
48+
var time = ParseTime (match.Groups ["timestamp"].Value);
49+
var span = time - start;
50+
Log.LogMessage (MessageImportance.Low, $"Time: {span.TotalMilliseconds.ToString ().PadLeft (6)}ms Message: {match.Groups ["message"].Value}");
51+
52+
match = runtimeInitRegex.Match (match.Groups ["message"].Value);
53+
if (match.Success)
54+
initEnd = time;
55+
last = time;
56+
}
57+
}
58+
59+
if (pid != -1) {
60+
Log.LogMessage (MessageImportance.Normal, " -- Performance summary --");
61+
Log.LogMessage (MessageImportance.Normal, $"Runtime init end: {(initEnd - start).TotalMilliseconds}ms");
62+
Log.LogMessage (MessageImportance.Normal, $"Last timing message: {(last - start).TotalMilliseconds}ms");
63+
64+
if (ResultsFilename != null)
65+
File.WriteAllText (Path.Combine (Path.GetDirectoryName (ResultsFilename), $"Test-{ApplicationPackageName}-times.csv"),
66+
$"init,last\n{(initEnd - start).TotalMilliseconds},{(last - start).TotalMilliseconds}");
67+
} else
68+
Log.LogWarning ("Wasn't able to collect the performance data");
69+
70+
reader.Close ();
71+
}
72+
73+
return true;
74+
}
75+
76+
static Regex timeRegex = new Regex (@"(?<month>\d+)-(?<day>\d+)\s+(?<hour>\d+):(?<minute>\d+):(?<second>\d+)\.(?<millisecond>\d+)");
77+
DateTime ParseTime (string s)
78+
{
79+
var match = timeRegex.Match (s);
80+
if (!match.Success)
81+
throw new InvalidOperationException ($"Unable to parse time: '{s}'");
82+
83+
// we don't handle year boundary here as the logcat timestamp doesn't include year information
84+
return new DateTime (DateTime.Now.Year,
85+
int.Parse (match.Groups ["month"].Value),
86+
int.Parse (match.Groups ["day"].Value),
87+
int.Parse (match.Groups ["hour"].Value),
88+
int.Parse (match.Groups ["minute"].Value),
89+
int.Parse (match.Groups ["second"].Value),
90+
int.Parse (match.Groups ["millisecond"].Value));
91+
}
92+
}
93+
}

‎build-tools/xa-prep-tasks/xa-prep-tasks.csproj‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -50,6 +50,7 @@
5050
<Compile Include="Xamarin.Android.BuildTools.PrepTasks\PrepareInstall.cs" />
5151
<Compile Include="Xamarin.Android.BuildTools.PrepTasks\AcceptAndroidSdkLicenses.cs" />
5252
<Compile Include="Xamarin.Android.BuildTools.PrepTasks\Sleep.cs" />
53+
<Compile Include="Xamarin.Android.BuildTools.PrepTasks\ProcessLogcatTiming.cs" />
5354
</ItemGroup>
5455
<Import Project="$(MSBuildBinPath)\Microsoft.CSharp.targets" />
5556
<Import Project="xa-prep-tasks.targets" />

0 commit comments

Comments
 (0)