Skip to content

Commit 7f6ed39

Browse files
ivbergivberg
authored
Logcat Durations - Add Kernel Boot, netd and RenderEngine durations (#72)
* Logcat Durations - Add Kernel Boot, netd and RenderEngine durations. Change default duration table view to longest durations
1 parent efa848b commit 7f6ed39

File tree

4 files changed

+78
-16
lines changed

4 files changed

+78
-16
lines changed

‎LinuxLogParsers/LinuxLogParser/AndroidLogcat/AndroidLogcatLogParser.cs‎

Lines changed: 54 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@
1010
using System.Diagnostics;
1111
using System.Globalization;
1212
using System.IO;
13+
using System.Linq;
1314
using System.Text;
1415
using System.Text.RegularExpressions;
1516
using System.Threading;
@@ -30,6 +31,7 @@ public class AndroidLogcatLogParser : LogParserBase<AndroidLogcatLogParsedEntry,
3031

3132
const long SECONDS_TO_NS = 1000000000;
3233
const long MS_TO_NS = 1000000;
34+
const long US_TO_NS = 1000;
3335
static readonly TimestampDelta OneNanoSecondTimestampDelta = new TimestampDelta(1); // At least 1ns timestamp for duration
3436

3537
public AndroidLogcatLogParser(string[] filePaths) : base(filePaths)
@@ -55,7 +57,6 @@ public override void ProcessSource(
5557
string line = string.Empty;
5658
var logEntries = new List<LogEntry>();
5759
var durationLogEntries = new List<DurationLogEntry>();
58-
LogEntry logEntry = null;
5960

6061
string timeDateFormat = null;
6162

@@ -72,6 +73,7 @@ public override void ProcessSource(
7273

7374
while ((line = file.ReadLine()) != null)
7475
{
76+
LogEntry logEntry = null;
7577
// Optimization - don't save blank lines
7678
if (line == String.Empty)
7779
{
@@ -223,6 +225,24 @@ public override void ProcessSource(
223225
durationLogEntry = LogEntryFromDurationMs(durationMs, logEntry, logEntry.Tag);
224226
}
225227
}
228+
// "Creating child chains: 13886us" - UserDebug
229+
else if (logEntry.Tag == "netd" && logEntry.Message.EndsWith("us"))
230+
{
231+
var messageSplit = logEntry.Message.Split();
232+
if (int.TryParse(messageSplit[^1].Replace("us", String.Empty), out int durationUs))
233+
{
234+
durationLogEntry = LogEntryFromDurationUs(durationUs, logEntry, logEntry.Tag);
235+
}
236+
}
237+
// "RenderEngine: shader cache generated - 48 shaders in 1452.951172 ms" - UserDebug
238+
else if (logEntry.Tag == "RenderEngine" && logEntry.Message.StartsWith("shader cache generated") && logEntry.Message.EndsWith(" ms"))
239+
{
240+
var messageSplit = logEntry.Message.Split();
241+
if (messageSplit.Length >= 9 && double.TryParse(messageSplit[7], out double durationMs))
242+
{
243+
durationLogEntry = LogEntryFromDurationMs(durationMs, logEntry, logEntry.Tag);
244+
}
245+
}
226246
// Android 12
227247
else if (logEntry.Tag == "ServiceManager" && logEntry.Message.Contains("successful after waiting"))
228248
{
@@ -262,7 +282,6 @@ public override void ProcessSource(
262282
if (durationLogEntry != null)
263283
{
264284
durationLogEntries.Add(durationLogEntry);
265-
dataProcessor.ProcessDataElement(durationLogEntry, Context, cancellationToken);
266285
}
267286
}
268287
else
@@ -279,24 +298,50 @@ public override void ProcessSource(
279298
if (logEntry != null)
280299
{
281300
logEntries.Add(logEntry);
282-
dataProcessor.ProcessDataElement(logEntry, Context, cancellationToken);
283301
}
284302

285303
currentLineNumber++;
286304
}
287305

288-
// Now adjust to start of trace
306+
// Synthetic durations
307+
308+
// Kernel Boot
309+
var kernelStart = logEntries.SingleOrDefault(f => f.LineNumber <= 100 && f.Tag == String.Empty && f.Message.StartsWith("Linux version"));
310+
var initStart = logEntries.SingleOrDefault(f => f.Tag == "init" && f.Message == "init first stage started!");
311+
if (kernelStart != null && initStart != null)
312+
{
313+
const string kernelBoot = "Kernel Boot";
314+
var kernelBootLogEntry = new DurationLogEntry()
315+
{
316+
StartTimestamp = kernelStart.Timestamp,
317+
EndTimestamp = initStart.Timestamp,
318+
Duration = initStart.Timestamp - kernelStart.Timestamp,
319+
FilePath = initStart.FilePath,
320+
LineNumber = initStart.LineNumber,
321+
PID = initStart.PID,
322+
TID = initStart.TID,
323+
Priority = initStart.Priority,
324+
Message = kernelBoot,
325+
Name = kernelBoot,
326+
};
327+
durationLogEntries.Add(kernelBootLogEntry);
328+
}
329+
330+
// Now adjust times to start of earliest message given out of order timestamps
289331
foreach (var le in logEntries)
290332
{
291333
if (le.Timestamp != Timestamp.MinValue)
292334
{
293335
le.Timestamp = Timestamp.FromNanoseconds(le.Timestamp.ToNanoseconds - startNanoSeconds);
294336
}
337+
dataProcessor.ProcessDataElement(le, Context, cancellationToken);
295338
}
296339
foreach (var durationLogEntry in durationLogEntries)
297340
{
298341
durationLogEntry.StartTimestamp = Timestamp.FromNanoseconds(durationLogEntry.StartTimestamp.ToNanoseconds - startNanoSeconds);
299342
durationLogEntry.EndTimestamp = Timestamp.FromNanoseconds(durationLogEntry.EndTimestamp.ToNanoseconds - startNanoSeconds);
343+
344+
dataProcessor.ProcessDataElement(durationLogEntry, Context, cancellationToken);
300345
}
301346

302347
contentDictionary[path] = logEntries.AsReadOnly();
@@ -337,6 +382,11 @@ private DurationLogEntry LogEntryFromDurationMs(double durationMs, LogEntry logE
337382
return LogEntryFromDurationNs((long) (durationMs * MS_TO_NS), logEntry, name);
338383
}
339384

385+
private DurationLogEntry LogEntryFromDurationUs(int durationUs, LogEntry logEntry, string name)
386+
{
387+
return LogEntryFromDurationNs(durationUs * US_TO_NS, logEntry, name);
388+
}
389+
340390
private DurationLogEntry LogEntryFromDurationNs(long durationNs, LogEntry logEntry, string name)
341391
{
342392
if (durationNs == 0)

‎LinuxLogParsers/LinuxLogParsersUnitTest/LinuxLogParsersUnitTest.cs‎

Lines changed: 12 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -116,16 +116,22 @@ public void AndroidLogcat()
116116
Assert.IsTrue(eventData.DurationLogEntries[1].Duration.ToMilliseconds == 53);
117117
Assert.IsTrue((eventData.DurationLogEntries[1].EndTimestamp - eventData.DurationLogEntries[1].StartTimestamp).ToMilliseconds == 53);
118118

119-
Assert.IsTrue(eventData.DurationLogEntries.Count == 1025);
119+
Assert.IsTrue(eventData.DurationLogEntries.Count == 1039);
120120

121121
// MakeWindowManagerServiceReady took to complete: 3ms
122-
Assert.IsTrue(eventData.DurationLogEntries[455].Name == "MakeWindowManagerServiceReady");
123-
Assert.IsTrue(eventData.DurationLogEntries[455].Duration.ToMilliseconds == 3);
124-
Assert.IsTrue((eventData.DurationLogEntries[455].EndTimestamp - eventData.DurationLogEntries[455].StartTimestamp).ToMilliseconds == 3);
122+
// eventData.DurationLogEntries.IndexOf(eventData.DurationLogEntries.Single(f => f.Name == "MakeWindowManagerServiceReady"))
123+
Assert.IsTrue(eventData.DurationLogEntries[468].Name == "MakeWindowManagerServiceReady");
124+
Assert.IsTrue(eventData.DurationLogEntries[468].Duration.ToMilliseconds == 3);
125+
Assert.IsTrue((eventData.DurationLogEntries[468].EndTimestamp - eventData.DurationLogEntries[468].StartTimestamp).ToMilliseconds == 3);
125126

126127
// Looper : Slow delivery took 2033ms main h=android.app.ActivityThread$H c=null m=156
127-
Assert.IsTrue(eventData.DurationLogEntries[921].Name == "main h=android.app.ActivityThread$H");
128-
Assert.IsTrue(eventData.DurationLogEntries[921].Duration.ToMilliseconds == 2033);
128+
Assert.IsTrue(eventData.DurationLogEntries[934].Name == "main h=android.app.ActivityThread$H");
129+
Assert.IsTrue(eventData.DurationLogEntries[934].Duration.ToMilliseconds == 2033);
130+
131+
132+
// Kernel Boot
133+
Assert.IsTrue(eventData.DurationLogEntries[^1].Name == "Kernel Boot");
134+
Assert.IsTrue(eventData.DurationLogEntries[^1].Duration.ToMilliseconds == 1906);
129135
}
130136

131137
[TestMethod]

‎LinuxLogParsers/LinuxPlugins-MicrosoftPerformanceToolkSDK/AndroidLogCat/AndroidLogcat.csproj‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -2,14 +2,14 @@
22

33
<PropertyGroup>
44
<TargetFramework>netstandard2.1</TargetFramework>
5-
<Version>1.2</Version>
5+
<Version>1.3.2</Version>
66
<PackageRequireLicenseAcceptance>true</PackageRequireLicenseAcceptance>
77
<RootNamespace>Android Logcat</RootNamespace>
88
<Authors>Microsoft</Authors>
99
<Company>Microsoft Corp.</Company>
1010
<Product>Performance ToolKit</Product>
1111
<Description>Contains the datasource plugin to parse Android Logcat log files.</Description>
12-
<PackageId>Microsoft.Performance.Toolkit.Plugins.Android LogcatPlugin</PackageId>
12+
<PackageId>Microsoft.Performance.Toolkit.Plugins.AndroidLogcatPlugin</PackageId>
1313
<Copyright>© Microsoft Corporation. All rights reserved.</Copyright>
1414
<RepositoryUrl>https://github.com/microsoft/Microsoft-Performance-Tools-Linux-Android</RepositoryUrl>
1515
<PackageProjectUrl>https://github.com/microsoft/Microsoft-Performance-Tools-Linux-Android</PackageProjectUrl>

‎LinuxLogParsers/LinuxPlugins-MicrosoftPerformanceToolkSDK/AndroidLogCat/Tables/DurationTable.cs‎

Lines changed: 10 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -59,7 +59,12 @@ public static class DurationTable
5959

6060
private static readonly ColumnConfiguration LineNumberColumn = new ColumnConfiguration(
6161
new ColumnMetadata(new Guid("{EDBD9BAF-0BD8-43D7-9752-BFCEF3FCBC13}"), "Line Number", "Ordering of the lines in the file"),
62-
new UIHints { Width = 80 });
62+
new UIHints
63+
{
64+
SortOrder = SortOrder.Ascending,
65+
SortPriority = 1,
66+
Width = 80,
67+
});
6368

6469
private static readonly ColumnConfiguration PIDColumn = new ColumnConfiguration(
6570
new ColumnMetadata(new Guid("{F75CD977-60C7-4CC3-9AB4-94ED44FFDC21}"), "PID", "The process ID that produced the message."),
@@ -107,9 +112,9 @@ public static void BuildTable(ITableBuilder tableBuilder, IDataExtensionRetrieva
107112
Columns = new[]
108113
{
109114
FileNameColumn,
115+
LineNumberColumn,
110116
NameColumn,
111117
TableConfiguration.PivotColumn,
112-
LineNumberColumn,
113118
PIDColumn,
114119
TIDColumn,
115120
PriorityColumn,
@@ -150,9 +155,10 @@ public static void BuildTable(ITableBuilder tableBuilder, IDataExtensionRetrieva
150155
longestDurationConfig.AddColumnRole(ColumnRole.EndTime, EndTimestampColumn);
151156
longestDurationConfig.AddColumnRole(ColumnRole.Duration, DurationColumnOrderedMax);
152157

153-
tableBuilder.AddTableConfiguration(timeOrderConfig)
158+
tableBuilder
159+
.AddTableConfiguration(timeOrderConfig)
154160
.AddTableConfiguration(longestDurationConfig)
155-
.SetDefaultTableConfiguration(timeOrderConfig)
161+
.SetDefaultTableConfiguration(longestDurationConfig)
156162
.SetRowCount(durationEntries.Count)
157163
.AddColumn(NameColumn, nameProjection)
158164
.AddColumn(FileNameColumn, fileNameProjection)

0 commit comments

Comments
 (0)