Skip to content

Commit f8423bf

Browse files
ivbergivberg
authored
Add support for Android Logcat txt based parsing. (#70)
* Add support for Android Logcat txt based parsing. This is because Perfetto doesn't support kernel boot tracing at all, nor post-kernel start boot tracing until Android 13. Like other txt based log support - this gives free support for relative timestamps, measuring time between events, etc. Also can group by component Tag, Priority, PID, or TID * Add support for parsing boot duration info & utfoffset.txt hint file if the trace is not being opened in the same timezone it was captured in
1 parent 1620618 commit f8423bf

21 files changed

+7188
-168
lines changed

‎LinuxLogParsers/LinuxLogParser/AndroidLogcat/AndroidLogcatLogParsedEntry.cs

Lines changed: 88 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,88 @@
1+
// Copyright (c) Microsoft Corporation.
2+
// Licensed under the MIT License.
3+
4+
using Microsoft.Performance.SDK;
5+
using Microsoft.Performance.SDK.Extensibility;
6+
7+
namespace LinuxLogParser.AndroidLogcat
8+
{
9+
public enum LogParsedDataKey
10+
{
11+
GeneralLog
12+
}
13+
14+
public class AndroidLogcatLogParsedEntry : IKeyedDataType<LogParsedDataKey>
15+
{
16+
private readonly LogParsedDataKey key;
17+
18+
public AndroidLogcatLogParsedEntry(LogParsedDataKey key)
19+
{
20+
this.key = key;
21+
}
22+
23+
public int CompareTo(LogParsedDataKey other)
24+
{
25+
return key.CompareTo(other);
26+
}
27+
28+
public LogParsedDataKey GetKey()
29+
{
30+
return key;
31+
}
32+
}
33+
34+
/// <summary>
35+
/// Per https://developer.android.com/studio/debug/am-logcat
36+
/// date time PID TID priority tag: message
37+
/// Example: "12-13 10:32:24.869 26 26 I Checkpoint: cp_prepareCheckpoint called"
38+
/// </summary>
39+
public class LogEntry: AndroidLogcatLogParsedEntry
40+
{
41+
public Timestamp Timestamp;
42+
public string FilePath;
43+
public ulong LineNumber;
44+
public uint PID;
45+
public uint TID;
46+
public string Priority;
47+
public string Tag;
48+
public string Message;
49+
50+
public LogEntry(): base(LogParsedDataKey.GeneralLog)
51+
{
52+
}
53+
}
54+
55+
public class DurationLogEntry : AndroidLogcatLogParsedEntry
56+
{
57+
public Timestamp StartTimestamp;
58+
public Timestamp EndTimestamp;
59+
public TimestampDelta Duration;
60+
public string FilePath;
61+
public ulong LineNumber;
62+
public uint PID;
63+
public uint TID;
64+
public string Priority;
65+
public string Tag;
66+
public string Message;
67+
public string Name;
68+
69+
public DurationLogEntry() : base(LogParsedDataKey.GeneralLog)
70+
{
71+
}
72+
73+
public DurationLogEntry(LogEntry logEntry, Timestamp startTimestamp, TimestampDelta duration, string name) : base(LogParsedDataKey.GeneralLog)
74+
{
75+
StartTimestamp = startTimestamp;
76+
EndTimestamp = logEntry.Timestamp;
77+
Duration = duration;
78+
FilePath = logEntry.FilePath;
79+
LineNumber = logEntry.LineNumber;
80+
PID = logEntry.PID;
81+
TID = logEntry.TID;
82+
Priority = logEntry.Priority;
83+
Tag = logEntry.Tag;
84+
Message = logEntry.Message;
85+
Name = name;
86+
}
87+
}
88+
}

‎LinuxLogParsers/LinuxLogParser/AndroidLogcat/AndroidLogcatLogParser.cs

Lines changed: 249 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,249 @@
1+
// Copyright (c) Microsoft Corporation.
2+
// Licensed under the MIT License.
3+
4+
using LinuxLogParserCore;
5+
using Microsoft.Performance.SDK;
6+
using Microsoft.Performance.SDK.Extensibility.SourceParsing;
7+
using Microsoft.Performance.SDK.Processing;
8+
using System;
9+
using System.Collections.Generic;
10+
using System.Diagnostics;
11+
using System.Globalization;
12+
using System.IO;
13+
using System.Text;
14+
using System.Text.RegularExpressions;
15+
using System.Threading;
16+
17+
namespace LinuxLogParser.AndroidLogcat
18+
{
19+
public class AndroidLogcatLogParser : LogParserBase<AndroidLogcatLogParsedEntry, LogParsedDataKey>
20+
{
21+
public override string Id => SourceParserIds.AndroidLogcatLog;
22+
public override DataSourceInfo DataSourceInfo => dataSourceInfo;
23+
24+
private DataSourceInfo dataSourceInfo;
25+
26+
/// Per https://developer.android.com/studio/debug/am-logcat
27+
/// date time PID TID priority tag: message
28+
/// Example: "12-13 10:32:24.869 26 26 I Checkpoint: cp_prepareCheckpoint called"
29+
public static Regex AndroidLogCatRegex = new Regex(@"^(.{18})\s+(\d+)\s+(\d+)\s+(\S) (.+?)\s?: (.*)$");
30+
31+
const int SECONDS_TO_NS = 1000000000;
32+
const int MS_TO_NS = 1000000;
33+
34+
public AndroidLogcatLogParser(string[] filePaths) : base(filePaths)
35+
{
36+
}
37+
38+
public override void ProcessSource(
39+
ISourceDataProcessor<AndroidLogcatLogParsedEntry, LogContext, LogParsedDataKey> dataProcessor,
40+
ILogger logger, IProgress<int> progress, CancellationToken cancellationToken)
41+
{
42+
var contentDictionary = new Dictionary<string, IReadOnlyList<LogEntry>>();
43+
Timestamp oldestTimestamp = new Timestamp(long.MaxValue);
44+
Timestamp newestTimestamp = new Timestamp(long.MinValue);
45+
long startNanoSeconds = 0;
46+
DateTime fileStartTime = default;
47+
var dateTimeCultureInfo = new CultureInfo("en-US");
48+
var oneNanoSecondTimestampDelta = new TimestampDelta(1); // At least 1ns timestamp for duration
49+
double? utcOffsetInHours = null;
50+
51+
foreach (var path in FilePaths)
52+
{
53+
ulong currentLineNumber = 1;
54+
var file = new System.IO.StreamReader(path);
55+
string line = string.Empty;
56+
var logEntries = new List<LogEntry>();
57+
var durationLogEntries = new List<DurationLogEntry>();
58+
LogEntry logEntry = null;
59+
60+
var rootFolder = Path.GetDirectoryName(path);
61+
var utcOffsetFilePath = Path.Combine(rootFolder, "utcoffset.txt");
62+
if (File.Exists(utcOffsetFilePath))
63+
{
64+
var utcOffSetStr = File.ReadAllText(utcOffsetFilePath);
65+
if (double.TryParse(utcOffSetStr, out double utcOffsetTmp))
66+
{
67+
utcOffsetInHours = utcOffsetTmp;
68+
}
69+
}
70+
71+
while ((line = file.ReadLine()) != null)
72+
{
73+
// Optimization - don't save blank lines
74+
if (line == String.Empty)
75+
{
76+
currentLineNumber++;
77+
continue;
78+
}
79+
80+
var androidLogCatMatch = AndroidLogCatRegex.Match(line);
81+
82+
// First, we check if the line is a new log entry if it matched Regex and by trying to parse its timestamp
83+
if (androidLogCatMatch.Success &&
84+
androidLogCatMatch.Groups.Count >= 7 &&
85+
DateTime.TryParseExact(androidLogCatMatch.Groups[1].Value, "MM-dd HH:mm:ss.fff", dateTimeCultureInfo, DateTimeStyles.None, out DateTime parsedTime))
86+
{
87+
var timeStamp = Timestamp.FromNanoseconds(parsedTime.Ticks * 100);
88+
89+
if (timeStamp < oldestTimestamp)
90+
{
91+
oldestTimestamp = timeStamp;
92+
fileStartTime = parsedTime;
93+
startNanoSeconds = oldestTimestamp.ToNanoseconds;
94+
}
95+
if (timeStamp > newestTimestamp)
96+
{
97+
newestTimestamp = timeStamp;
98+
}
99+
100+
logEntry = new LogEntry
101+
{
102+
Timestamp = new Timestamp(timeStamp.ToNanoseconds), // We can't subtract startNanoSeconds here because logs are not necessarily time ordered
103+
FilePath = path,
104+
LineNumber = currentLineNumber,
105+
PID = uint.Parse(androidLogCatMatch.Groups[2].Value),
106+
TID = uint.Parse(androidLogCatMatch.Groups[3].Value),
107+
Priority = Utilities.Common.StringIntern(androidLogCatMatch.Groups[4].Value),
108+
Tag = Utilities.Common.StringIntern(androidLogCatMatch.Groups[5].Value.Trim()),
109+
Message = androidLogCatMatch.Groups[6].Value,
110+
};
111+
112+
// Specialized Duration parsing
113+
DurationLogEntry durationLogEntry = null;
114+
if (logEntry.Tag == "init" && logEntry.Message.Contains("took"))
115+
{
116+
var messageSplit = logEntry.Message.Split();
117+
var firstSingleQuoteIdx = logEntry.Message.IndexOf('\'');
118+
var secondSingleQuoteIdx = logEntry.Message.IndexOf('\'', firstSingleQuoteIdx+1);
119+
var name = logEntry.Message.Substring(firstSingleQuoteIdx+1, secondSingleQuoteIdx - firstSingleQuoteIdx - 1);
120+
// Command 'write /dev/cpuctl/cpu.rt_period_us 1000000' action=init (/system/etc/init/hw/init.rc:271) took 0ms and failed: ....
121+
if (logEntry.Message.Contains("0ms"))
122+
{
123+
durationLogEntry = new DurationLogEntry(logEntry, logEntry.Timestamp - oneNanoSecondTimestampDelta, oneNanoSecondTimestampDelta, name);
124+
}
125+
// Service 'boringssl_self_test32_vendor' (pid 18) exited with status 0 waiting took 0.022000 seconds
126+
127+
if (messageSplit[^3] == "took" && messageSplit[^1] == "seconds")
128+
{
129+
if (double.TryParse(messageSplit[^2], out double durationSeconds))
130+
{
131+
var duration = new TimestampDelta((long)(durationSeconds * SECONDS_TO_NS));
132+
durationLogEntry = new DurationLogEntry(logEntry, logEntry.Timestamp - duration, duration, name);
133+
}
134+
}
135+
// Command 'mount_all /fstab.${ro.hardware}' action=fs (/vendor/etc/init/init.windows_x86_64.rc:14) took 1054ms and succeeded
136+
else if(messageSplit[^4] == "took" && messageSplit[^1] == "succeeded")
137+
{
138+
if (int.TryParse(messageSplit[^3].Replace("ms", String.Empty), out int durationMs))
139+
{
140+
var duration = new TimestampDelta(durationMs * MS_TO_NS);
141+
durationLogEntry = new DurationLogEntry(logEntry, logEntry.Timestamp - duration, duration, name);
142+
}
143+
}
144+
// Service 'disable_lro' (pid 39) exited with status 0 oneshot service took 0.006000 seconds in background
145+
else if (messageSplit[^5] == "took" && messageSplit[^1] == "background")
146+
{
147+
if (double.TryParse(messageSplit[^4], out double durationSeconds))
148+
{
149+
var duration = new TimestampDelta((long)(durationSeconds * SECONDS_TO_NS));
150+
durationLogEntry = new DurationLogEntry(logEntry, logEntry.Timestamp - duration, duration, name);
151+
}
152+
}
153+
// Command 'rm /data/user/0' action=post-fs-data (/system/etc/init/hw/init.rc:706) took 1ms and failed: unlink() failed: Is a directory
154+
else
155+
{
156+
var tookIndex = Array.IndexOf(messageSplit, "took");
157+
var afterTook = messageSplit[tookIndex + 1];
158+
if (afterTook.Contains("ms"))
159+
{
160+
if (int.TryParse(afterTook.Replace("ms", String.Empty), out int durationMs))
161+
{
162+
var duration = new TimestampDelta(durationMs * MS_TO_NS);
163+
durationLogEntry = new DurationLogEntry(logEntry, logEntry.Timestamp - duration, duration, name);
164+
}
165+
}
166+
}
167+
}
168+
// Zygote32Timing: PostZygoteInitGC took to complete: 61ms
169+
else if (logEntry.Tag.Contains("Timing") && logEntry.Message.Contains("took to complete"))
170+
{
171+
var messageSplit = logEntry.Message.Split();
172+
var name = messageSplit[0];
173+
if (int.TryParse(messageSplit[^1].Replace("ms", String.Empty), out int durationMs))
174+
{
175+
if (durationMs == 0)
176+
{
177+
durationLogEntry = new DurationLogEntry(logEntry, logEntry.Timestamp - oneNanoSecondTimestampDelta, oneNanoSecondTimestampDelta, name);
178+
}
179+
else
180+
{
181+
var duration = new TimestampDelta(durationMs * MS_TO_NS);
182+
durationLogEntry = new DurationLogEntry(logEntry, logEntry.Timestamp - duration, duration, name);
183+
}
184+
}
185+
}
186+
187+
if (durationLogEntry != null)
188+
{
189+
durationLogEntries.Add(durationLogEntry);
190+
dataProcessor.ProcessDataElement(durationLogEntry, Context, cancellationToken);
191+
}
192+
}
193+
else
194+
{
195+
logEntry = new LogEntry
196+
{
197+
Timestamp = Timestamp.MinValue,
198+
FilePath = path,
199+
LineNumber = currentLineNumber,
200+
Message = line,
201+
};
202+
}
203+
204+
if (logEntry != null)
205+
{
206+
logEntries.Add(logEntry);
207+
dataProcessor.ProcessDataElement(logEntry, Context, cancellationToken);
208+
}
209+
210+
currentLineNumber++;
211+
}
212+
213+
// Now adjust to start of trace
214+
foreach (var le in logEntries)
215+
{
216+
if (le.Timestamp != Timestamp.MinValue)
217+
{
218+
le.Timestamp = Timestamp.FromNanoseconds(le.Timestamp.ToNanoseconds - startNanoSeconds);
219+
}
220+
}
221+
foreach (var durationLogEntry in durationLogEntries)
222+
{
223+
durationLogEntry.StartTimestamp = Timestamp.FromNanoseconds(durationLogEntry.StartTimestamp.ToNanoseconds - startNanoSeconds);
224+
durationLogEntry.EndTimestamp = Timestamp.FromNanoseconds(durationLogEntry.EndTimestamp.ToNanoseconds - startNanoSeconds);
225+
}
226+
227+
contentDictionary[path] = logEntries.AsReadOnly();
228+
229+
file.Close();
230+
231+
--currentLineNumber;
232+
Context.UpdateFileMetadata(path, new FileMetadata(currentLineNumber));
233+
}
234+
235+
var offsetEndTimestamp = new Timestamp(newestTimestamp.ToNanoseconds - startNanoSeconds);
236+
237+
if (utcOffsetInHours.HasValue)
238+
{
239+
// Log is in local time (not UTC) but we can use utcOffset.txt hint file to modify
240+
var fileStartTimeUtc = fileStartTime.Subtract(new TimeSpan(0, (int) (utcOffsetInHours.Value * 60), 0));
241+
dataSourceInfo = new DataSourceInfo(0, offsetEndTimestamp.ToNanoseconds, DateTime.FromFileTimeUtc(fileStartTimeUtc.ToFileTimeUtc()));
242+
}
243+
else
244+
{
245+
dataSourceInfo = new DataSourceInfo(0, offsetEndTimestamp.ToNanoseconds, DateTime.FromFileTimeUtc(fileStartTime.ToFileTime())); // Treat as current locale local time (default)
246+
}
247+
}
248+
}
249+
}

‎LinuxLogParsers/LinuxLogParser/DmesgIsoLog/DmesgIsoLogParser.cs

Lines changed: 11 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -58,8 +58,8 @@ public override void ProcessSource(
5858
Timestamp oldestTimestamp = new Timestamp(long.MaxValue);
5959
Timestamp newestTImestamp = new Timestamp(long.MinValue);
6060
long startNanoSeconds = 0;
61-
DateTime fileStartTime = default(DateTime);
62-
DateTime parsedTime = default(DateTime);
61+
DateTime fileStartTime = default;
62+
DateTime parsedTime = default;
6363
var dateTimeCultureInfo = new CultureInfo("en-US");
6464

6565
foreach (var path in FilePaths)
@@ -73,17 +73,19 @@ public override void ProcessSource(
7373
while ((line = file.ReadLine()) != null)
7474
{
7575
//First, we check if the line is a new log entry by trying to parse its timestamp
76-
if (line.Length >= 31 && DateTime.TryParseExact(line.Substring(0, 31), "yyyy-MM-ddTHH:mm:ss,ffffffK", dateTimeCultureInfo, DateTimeStyles.None, out parsedTime))
76+
if (line.Length >= 31 && DateTime.TryParseExact(line[..31], "yyyy-MM-ddTHH:mm:ss,ffffffK", dateTimeCultureInfo, DateTimeStyles.None, out parsedTime))
7777
{
7878
if (lastEntry != null)
7979
{
8080
dataProcessor.ProcessDataElement(lastEntry, Context, cancellationToken);
8181
}
8282

83-
lastEntry = new LogEntry();
84-
lastEntry.filePath = path;
85-
lastEntry.lineNumber = currentLineNumber;
86-
lastEntry.rawLog = line.Substring(32);
83+
lastEntry = new LogEntry
84+
{
85+
filePath = path,
86+
lineNumber = currentLineNumber,
87+
rawLog = line[32..]
88+
};
8789

8890
lineContent = lastEntry.rawLog.Split(':');
8991

@@ -108,7 +110,7 @@ public override void ProcessSource(
108110
// Character ':' occurs multiple times in the message, and at least once in the beginning
109111
// We proceed to try to infer entity, metadata and topic
110112
firstSlice = lineContent[0].Split(' ');
111-
var lastSubstring = firstSlice[firstSlice.Length - 1];
113+
var lastSubstring = firstSlice[^1];
112114
int contentIndex = 2;
113115
if (firstSlice.Length > 1 && this.IsNumberFormat(lastSubstring) && this.IsNumberFormat(lineContent[1]))
114116
{
@@ -127,7 +129,7 @@ public override void ProcessSource(
127129

128130
lastEntry.metadata = builder.ToString();
129131

130-
lastEntry.entity = lineContent[0].Substring(0, lineContent[0].Length - lastSubstring.Length - 1);
132+
lastEntry.entity = lineContent[0][..(lineContent[0].Length - lastSubstring.Length - 1)];
131133

132134
if ((contentIndex < lineContent.Length - 1) && !IsPCIinfo(lineContent[contentIndex]))
133135
{

0 commit comments

Comments
 (0)