JD2022-TU1/main/extern/ProfileEventViewer4/LoadingLogsToTrace.cs

988 lines
No EOL
46 KiB
C#

using System;
using System.Collections.Generic;
using System.Globalization;
using System.IO;
using System.Linq;
using System.Text;
using System.Windows.Forms;
using Time = System.Double;
using ObjectID = System.UInt64;
namespace ProfileEventViewer
{
static class LoadingLogsToTrace
{
public enum LoadingLogType
{
LoadingProfiler,
FastloadManager,
BigFileAsynchStream,
SoundStream,
Unknown
}
public static bool IsLoadingLog(string fileName)
{
return GetLoadingLogType(fileName) != LoadingLogType.Unknown;
}
private static LoadingLogType GetLoadingLogType(string fileName)
{
// Verify (very coarsely) of which loading log type the file is
try
{
if (Path.GetExtension(fileName).ToLower() != ".csv")
return LoadingLogType.Unknown;
using (StreamReader reader = File.OpenText(fileName))
{
string headerLine = reader.ReadLine();
// Not really rock-solid, but should do the trick for now...
if (headerLine.Contains("Cancelled"))
return LoadingLogType.LoadingProfiler;
else if (headerLine.Contains("Recycle"))
return LoadingLogType.BigFileAsynchStream;
else if (headerLine.Contains("Container"))
return LoadingLogType.FastloadManager;
else if (headerLine.Contains("Sound Type"))
return LoadingLogType.SoundStream;
}
}
catch { }
return LoadingLogType.Unknown;
}
public static string CreateTraceFromLoadingLogs(IEnumerable<string> fileNames)
{
List<string> logFileNames = new List<string>();
foreach (string fileName in fileNames)
{
if (!IsLoadingLog(fileName))
{
MessageBox.Show(string.Format("File {0} does not appear to be a loading log.\n\nPlease see the help for more information.", fileName), "Loading logs", MessageBoxButtons.OK, MessageBoxIcon.Warning);
continue;
}
logFileNames.Add(fileName);
}
SimplifiedTrace trace = new SimplifiedTrace();
foreach (string fileName in logFileNames)
{
LoadingLogType type = GetLoadingLogType(fileName);
using (StreamReader reader = File.OpenText(fileName))
{
reader.ReadLine(); // Skip header
if (type == LoadingLogType.LoadingProfiler)
{
ReadLoadingProfilerLog(reader, trace);
}
else if (type == LoadingLogType.BigFileAsynchStream)
{
ReadBigFileAsynchStreamLog(reader, trace, GetPriorityFromFilename(fileName));
}
else if (type == LoadingLogType.FastloadManager)
{
ReadFastloadManagerLog(reader, trace);
}
else if (type == LoadingLogType.SoundStream)
{
ReadSoundStreamLog(reader, trace);
}
}
}
if (logFileNames.Count > 0)
{
SaveFileDialog saveDialog = new SaveFileDialog();
saveDialog.DefaultExt = "pel2";
saveDialog.Filter = "Profile event log (*.pel2)|*.pel2";
saveDialog.Title = "Save Loading Logs Trace";
saveDialog.FileName = "loadingstat";
DialogResult result = saveDialog.ShowDialog();
if (result == DialogResult.OK)
{
trace.Write(saveDialog.FileName);
return saveDialog.FileName;
}
}
return null;
}
#region FastloadManager logs
private static int ReadFastloadManagerLog(StreamReader reader, SimplifiedTrace trace)
{
List<ObjectLoadingStat> stats = new List<ObjectLoadingStat>();
Dictionary<ObjectID, UInt32> containerProfiles = new Dictionary<ObjectID, UInt32>();
containerProfiles.Add(0, trace.NextProfileID);
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = "No Container", m_ProfileID = trace.NextProfileID });
Dictionary<ObjectID, UInt32> groupProfiles = new Dictionary<ObjectID, UInt32>();
groupProfiles.Add(0, trace.NextProfileID);
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = "No Group", m_ProfileID = trace.NextProfileID });
Dictionary<ObjectID, UInt32> postLoadProfiles = new Dictionary<ObjectID, UInt32>();
postLoadProfiles.Add(unchecked((ObjectID)PostLoadStep.Link), trace.NextProfileID);
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = "Link Requests", m_ProfileID = trace.NextProfileID });
postLoadProfiles.Add(unchecked((ObjectID)PostLoadStep.InitBeforeHandleActivation), trace.NextProfileID);
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = "Init Before Handle Activation", m_ProfileID = trace.NextProfileID });
postLoadProfiles.Add(unchecked((ObjectID)PostLoadStep.InitAfterHandleActivation), trace.NextProfileID);
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = "Init After Handle Activation", m_ProfileID = trace.NextProfileID });
postLoadProfiles.Add(unchecked((ObjectID)PostLoadStep.DelayedResources), trace.NextProfileID);
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = "Delayed Resources", m_ProfileID = trace.NextProfileID });
// Read the data
string line = reader.ReadLine();
while (line != null)
{
string[] tokens = line.Split(',');
if (tokens.Length != 9)
{
Console.WriteLine("Malformed line does not contain 9 tokens: \"{0}\"", line);
return 2;
}
ObjectLoadingStat stat = new ObjectLoadingStat();
stat.Key = ObjectID.Parse(tokens[0].Substring(2, tokens[0].Length - 2), NumberStyles.HexNumber, CultureInfo.InvariantCulture);
stat.Container = ObjectID.Parse(tokens[1].Substring(2, tokens[1].Length - 2), NumberStyles.HexNumber, CultureInfo.InvariantCulture);
stat.Group = ObjectID.Parse(tokens[2].Substring(2, tokens[2].Length - 2), NumberStyles.HexNumber, CultureInfo.InvariantCulture);
stat.Size = UInt32.Parse(tokens[3]);
stat.Source = UInt32.Parse(tokens[4]);
stat.StartTime = UInt64.Parse(tokens[5]);
stat.ReadHeaderTime = UInt64.Parse(tokens[6]);
stat.ReadTime = UInt64.Parse(tokens[7]);
stat.SkipTime = UInt64.Parse(tokens[8]);
UInt32 postLoadProfileIndex;
if (!postLoadProfiles.TryGetValue(stat.Key, out postLoadProfileIndex))
{
if (stat.SkipTime == 0)
{
if (stat.ReadHeaderTime < stat.StartTime)
throw new InvalidDataException(string.Format("FastloadManager log file corrupt when reading load event: stat.ReadHeaderTime ({0}) < stat.StartTime ({1}).", stat.ReadHeaderTime, stat.StartTime));
if (stat.ReadTime < stat.ReadHeaderTime)
throw new InvalidDataException(string.Format("FastloadManager log file corrupt when reading load event: stat.ReadTime ({0}) < stat.ReadHeaderTime ({1}).", stat.ReadTime, stat.ReadHeaderTime));
}
else
{
if (stat.SkipTime < stat.StartTime)
throw new InvalidDataException(string.Format("FastloadManager log file corrupt when reading load event: stat.SkipTime ({0}) < stat.StartTime ({1}).", stat.SkipTime, stat.StartTime));
}
stat.IsPostLoadEvent = false;
stat.HeaderProfile = new EventFileProfileDesc() { m_Name = string.Format("FileHeader 0x{0:x08} 0x{1:x08} {2} [{3}]", stat.Key, stat.Group, stat.Size, stat.Source), m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(stat.HeaderProfile);
stat.Profile = new EventFileProfileDesc() { m_Name = string.Format("File{4} 0x{0:x08} 0x{1:x08} {2} [{3}]", stat.Key, stat.Group, stat.Size, stat.Source, stat.ReadTime != 0 ? "Read" : "Skip"), m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(stat.Profile);
UInt32 containerProfileIndex;
if (!containerProfiles.TryGetValue(stat.Container, out containerProfileIndex))
{
containerProfileIndex = trace.NextProfileID;
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = string.Format("Container 0x{0:x08} [{1}]", stat.Container, stat.Source), m_ProfileID = trace.NextProfileID });
containerProfiles.Add(stat.Container, containerProfileIndex);
}
stat.ContainerProfile = trace.Profiles[(int)containerProfileIndex];
UInt32 groupProfileIndex;
if (!groupProfiles.TryGetValue(stat.Group, out groupProfileIndex))
{
groupProfileIndex = trace.NextProfileID;
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = string.Format("Group 0x{0:x08}", stat.Group), m_ProfileID = trace.NextProfileID });
groupProfiles.Add(stat.Group, groupProfileIndex);
}
stat.GroupProfile = trace.Profiles[(int)groupProfileIndex];
}
else
{
// Special case: post load!
if (stat.ReadTime < stat.StartTime)
throw new InvalidDataException(string.Format("FastloadManager log file corrupt when reading postload event: stat.ReadTime ({0}) < stat.StartTime ({1}).", stat.ReadTime, stat.StartTime));
stat.IsPostLoadEvent = true;
stat.PostLoadProfile = trace.Profiles[(int)postLoadProfileIndex];
}
stats.Add(stat);
line = reader.ReadLine();
}
// Create contexts.
EventFileThreadDesc context = new EventFileThreadDesc();
context.m_Name = "FastloadManager";
context.m_ThreadID = trace.NextContextID;
context.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(context);
// Create events
if (stats.Count > 0)
{
{
WriteEventStart(trace.ProfileEvents, context.m_ThreadID, stats[0].GroupProfile.m_ProfileID, stats[0].StartTime);
WriteEventStart(trace.ProfileEvents, context.m_ThreadID, stats[0].ContainerProfile.m_ProfileID, stats[0].StartTime);
if (stats[0].ReadTime != 0)
{
WriteEvent(trace.ProfileEvents, context.m_ThreadID, stats[0].HeaderProfile.m_ProfileID, stats[0].StartTime, stats[0].ReadHeaderTime);
WriteEvent(trace.ProfileEvents, context.m_ThreadID, stats[0].Profile.m_ProfileID, stats[0].ReadHeaderTime, stats[0].ReadTime);
}
else
{
WriteEvent(trace.ProfileEvents, context.m_ThreadID, stats[0].Profile.m_ProfileID, stats[0].StartTime, stats[0].SkipTime);
}
UInt64 endTime = (stats[0].ReadTime != 0 ? stats[0].ReadTime : stats[0].SkipTime);
WriteEvent(trace.ProfileEvents, context.m_ThreadID, stats[0].Profile.m_ProfileID, stats[0].ReadHeaderTime, endTime);
if (stats.Count == 1 || stats[0].Container == 0 || stats[0].Container != stats[1].Container)
WriteEventEnd(trace.ProfileEvents, context.m_ThreadID, stats[0].ContainerProfile.m_ProfileID, endTime);
if (stats.Count == 1 || stats[0].Group == 0 || stats[0].Group != stats[1].Group)
WriteEventEnd(trace.ProfileEvents, context.m_ThreadID, stats[0].GroupProfile.m_ProfileID, endTime);
}
for (int i = 1; i < stats.Count; ++i)
{
if (!stats[i].IsPostLoadEvent)
{
if (stats[i].Group != stats[i - 1].Group || stats[i].Group == 0)
WriteEventStart(trace.ProfileEvents, context.m_ThreadID, stats[i].GroupProfile.m_ProfileID, stats[i].StartTime);
if (stats[i].Container != stats[i - 1].Container || stats[i].Container == 0)
WriteEventStart(trace.ProfileEvents, context.m_ThreadID, stats[i].ContainerProfile.m_ProfileID, stats[i].StartTime);
if (stats[i].ReadTime != 0)
{
WriteEvent(trace.ProfileEvents, context.m_ThreadID, stats[i].HeaderProfile.m_ProfileID, stats[i].StartTime, stats[i].ReadHeaderTime);
WriteEvent(trace.ProfileEvents, context.m_ThreadID, stats[i].Profile.m_ProfileID, stats[i].ReadHeaderTime, stats[i].ReadTime);
}
else
{
WriteEvent(trace.ProfileEvents, context.m_ThreadID, stats[i].Profile.m_ProfileID, stats[i].StartTime, stats[i].SkipTime);
}
UInt64 endTime = (stats[i].ReadTime != 0 ? stats[i].ReadTime : stats[i].SkipTime);
if (i + 1 >= stats.Count || stats[i].Container == 0 || stats[i].Container != stats[i + 1].Container)
WriteEventEnd(trace.ProfileEvents, context.m_ThreadID, stats[i].ContainerProfile.m_ProfileID, endTime);
if (i + 1 >= stats.Count || stats[i].Group == 0 || stats[i].Group != stats[i + 1].Group)
WriteEventEnd(trace.ProfileEvents, context.m_ThreadID, stats[i].GroupProfile.m_ProfileID, endTime);
}
else
{
WriteEvent(trace.ProfileEvents, context.m_ThreadID, stats[i].PostLoadProfile.m_ProfileID, stats[i].StartTime, stats[i].ReadTime);
}
}
}
return 0;
}
private class ObjectLoadingStat
{
public ObjectID Key;
public ObjectID Group;
public ObjectID Container;
public UInt32 Size;
public UInt32 Source;
public UInt64 StartTime;
public UInt64 ReadHeaderTime; // 0 if SkipTime is set
public UInt64 ReadTime; // 0 if SkipTime is set
public UInt64 SkipTime;
public bool IsPostLoadEvent;
public EventFileProfileDesc HeaderProfile;
public EventFileProfileDesc Profile;
public EventFileProfileDesc ContainerProfile;
public EventFileProfileDesc GroupProfile;
public EventFileProfileDesc PostLoadProfile; // If this is used, the other profiles are not
}
enum PostLoadStep
{
Link = -1,
InitBeforeHandleActivation = -2,
InitAfterHandleActivation = -3,
DelayedResources = -4,
};
#endregion
#region BigFileAsynchStream logs
private static int ReadBigFileAsynchStreamLog(StreamReader reader, SimplifiedTrace trace, StreamingPriority priority)
{
List<PrefetchFileStat> files = new List<PrefetchFileStat>();
List<PrefetchChunkStat> chunks = new List<PrefetchChunkStat>();
HashSet<UInt32> chunkIndices = new HashSet<UInt32>();
EventFileProfileDesc recycleProfile = new EventFileProfileDesc() { m_Name = "No Group", m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(recycleProfile);
Dictionary<ObjectID, UInt32> groupProfiles = new Dictionary<ObjectID, UInt32>();
groupProfiles.Add(0, trace.NextProfileID);
EventFileProfileDesc noGroupProfile = new EventFileProfileDesc() { m_Name = "No Group", m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(noGroupProfile);
// Read the data
string line = reader.ReadLine();
while (line != null)
{
string[] tokens = line.Split(',');
if (tokens.Length != 11)
{
Console.WriteLine("Malformed line does not contain 11 tokens: \"{0}\"", line);
return 2;
}
if (tokens[0] == "File")
{
PrefetchFileStat file = new PrefetchFileStat();
file.Key = ObjectID.Parse(tokens[1].Substring(2, tokens[1].Length - 2), NumberStyles.HexNumber, CultureInfo.InvariantCulture);
file.Group = ObjectID.Parse(tokens[2].Substring(2, tokens[2].Length - 2), NumberStyles.HexNumber, CultureInfo.InvariantCulture);
file.Offset = UInt64.Parse(tokens[3]);
file.Size = UInt32.Parse(tokens[4]);
file.RequestStartTime = UInt64.Parse(tokens[5]);
file.StreamStartTime = UInt64.Parse(tokens[6]);
file.EndTime = UInt64.Parse(tokens[7]);
if (file.RequestStartTime > file.StreamStartTime)
throw new InvalidDataException(string.Format("BigFileAsynchStream log file corrupt: file.RequestStartTime ({0}) > file.StreamStartTime ({1}).", file.RequestStartTime, file.StreamStartTime));
if (file.StreamStartTime > file.EndTime)
throw new InvalidDataException(string.Format("BigFileAsynchStream log file corrupt: file.StreamStartTime ({0}) > file.EndTime ({1}).", file.StreamStartTime, file.EndTime));
file.Profile = new EventFileProfileDesc() { m_Name = string.Format("File 0x{0:x08} 0x{1:x08} {2} {3}", file.Key, file.Group, file.Offset, file.Size), m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(file.Profile);
UInt32 groupProfileIndex;
if (!groupProfiles.TryGetValue(file.Group, out groupProfileIndex))
{
groupProfileIndex = trace.NextProfileID;
trace.Profiles.Add(new EventFileProfileDesc() { m_Name = string.Format("Group 0x{0:x08}", file.Group), m_ProfileID = trace.NextProfileID });
groupProfiles.Add(file.Group, groupProfileIndex);
}
file.GroupProfile = trace.Profiles[(int)groupProfileIndex];
files.Add(file);
}
else // Chunk
{
PrefetchChunkStat chunk = new PrefetchChunkStat();
chunk.Index = UInt32.Parse(tokens[1]);
chunk.Offset = UInt64.Parse(tokens[3]);
chunk.Size = UInt32.Parse(tokens[4]);
chunk.StartTime = UInt64.Parse(tokens[6]);
chunk.EndTime = UInt64.Parse(tokens[7]);
chunk.RecycleTime = UInt64.Parse(tokens[8]);
if (chunk.EndTime < chunk.StartTime)
throw new InvalidDataException(string.Format("BigFileAsynchStream log file corrupt: chunk.EndTime ({0}) < chunk.StartTime ({1}).", chunk.EndTime, chunk.StartTime));
if (chunk.RecycleTime != 0 && chunk.RecycleTime < chunk.EndTime)
throw new InvalidDataException(string.Format("BigFileAsynchStream log file corrupt: chunk.RecycleTime ({0}) < chunk.EndTime ({1}).", chunk.RecycleTime, chunk.EndTime));
chunk.Profile = new EventFileProfileDesc() { m_Name = string.Format("Chunk {0} {1}", chunk.Offset, chunk.Size), m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(chunk.Profile);
chunkIndices.Add(chunk.Index);
chunks.Add(chunk);
}
line = reader.ReadLine();
}
// Create contexts.
EventFileThreadDesc fileContext = new EventFileThreadDesc();
fileContext.m_Name = string.Format("File Requests{0}", priority == StreamingPriority.High ? " - High" : "");
fileContext.m_ThreadID = trace.NextContextID;
fileContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(fileContext);
UInt32 baseChunkContextID = trace.NextContextID;
for (int i = 0; i < chunkIndices.Count; ++i)
{
EventFileThreadDesc context = new EventFileThreadDesc();
context.m_Name = string.Format("Prefetch Chunk {0}{1}", i, priority == StreamingPriority.High ? " - High" : "");
context.m_ThreadID = trace.NextContextID;
context.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(context);
}
// Create events
if (files.Count > 0)
{
WriteEventStart(trace.ProfileEvents, fileContext.m_ThreadID, files[0].GroupProfile.m_ProfileID, files[0].StreamStartTime);
WriteEvent(trace.ProfileEvents, fileContext.m_ThreadID, files[0].Profile.m_ProfileID, files[0].StreamStartTime, files[0].EndTime);
if (files.Count == 1 || files[0].Group == 0 || files[0].Group != files[1].Group)
WriteEventEnd(trace.ProfileEvents, fileContext.m_ThreadID, files[0].GroupProfile.m_ProfileID, files[0].EndTime);
trace.DataEvents.Add(new DataEvent { m_ContextID = fileContext.m_ThreadID, m_Data = string.Format("Request 0x{0:x08}", files[0].Key), m_Time = files[0].RequestStartTime });
for (int i = 1; i < files.Count; ++i)
{
if (files[i].Group != files[i - 1].Group || files[i].Group == 0)
WriteEventStart(trace.ProfileEvents, fileContext.m_ThreadID, files[i].GroupProfile.m_ProfileID, files[i].StreamStartTime);
WriteEvent(trace.ProfileEvents, fileContext.m_ThreadID, files[i].Profile.m_ProfileID, files[i].StreamStartTime, files[i].EndTime);
trace.DataEvents.Add(new DataEvent { m_ContextID = fileContext.m_ThreadID, m_Data = string.Format("Request 0x{0:x08}", files[i].Key), m_Time = files[i].RequestStartTime });
if (i + 1 >= files.Count || files[i].Group == 0 || files[i].Group != files[i + 1].Group)
WriteEventEnd(trace.ProfileEvents, fileContext.m_ThreadID, files[i].GroupProfile.m_ProfileID, files[i].EndTime);
}
//foreach (PrefetchFileStat file in files)
//{
// WriteEvent(profileEvents, fileContext.m_ThreadID, file.Profile.m_ProfileID, file.StreamStartTime, file.EndTime);
// dataEvents.Add(new DataEvent { m_ContextID = fileContext.m_ThreadID, m_Data = string.Format("Request 0x{0:x08}", file.Key), m_Time = file.RequestStartTime });
//}
}
foreach (PrefetchChunkStat chunk in chunks)
{
WriteEvent(trace.ProfileEvents, baseChunkContextID + chunk.Index, chunk.Profile.m_ProfileID, chunk.StartTime, chunk.EndTime);
if (chunk.RecycleTime != 0)
WriteEvent(trace.ProfileEvents, baseChunkContextID + chunk.Index, recycleProfile.m_ProfileID, chunk.EndTime, chunk.RecycleTime);
}
return 0;
}
private static StreamingPriority GetPriorityFromFilename(string fileName)
{
if (fileName.Contains("_H"))
return StreamingPriority.High;
return StreamingPriority.Normal;
}
private enum StreamingPriority
{
Normal,
High,
}
private struct PrefetchFileStat
{
public ObjectID Key;
public ObjectID Group;
public UInt64 Offset;
public UInt32 Size;
public UInt64 RequestStartTime;
public UInt64 StreamStartTime;
public UInt64 EndTime;
public EventFileProfileDesc Profile;
public EventFileProfileDesc GroupProfile;
}
private struct PrefetchChunkStat
{
public UInt32 Index;
public UInt64 Offset;
public UInt32 Size;
public UInt64 StartTime;
public UInt64 EndTime;
public UInt64 RecycleTime;
public EventFileProfileDesc Profile;
}
#endregion
#region Loading Profiler logs
private static int ReadLoadingProfilerLog(StreamReader reader, SimplifiedTrace trace)
{
List<LoadingProfilerStat> stats = new List<LoadingProfilerStat>();
EventFileProfileDesc whiteRoomProfile = new EventFileProfileDesc() { m_Name = "WhiteRoom", m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(whiteRoomProfile);
EventFileProfileDesc waitingProfile = new EventFileProfileDesc() { m_Name = "Waiting For Loading", m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(waitingProfile);
EventFileProfileDesc ghostProfile = new EventFileProfileDesc() { m_Name = "Ghosting", m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(ghostProfile);
// Read the data
string line = reader.ReadLine();
while (line != null)
{
string[] tokens = line.Split(',');
if (tokens.Length != 6)
{
Console.WriteLine("Malformed line does not contain 6 tokens: \"{0}\"", line);
return 2;
}
LoadingProfilerStat stat = new LoadingProfilerStat();
stat.ObjectID = ObjectID.Parse(tokens[0].Substring(2, tokens[0].Length - 2), NumberStyles.HexNumber, CultureInfo.InvariantCulture);
stat.AdditionalID = ObjectID.Parse(tokens[1].Substring(2, tokens[1].Length - 2), NumberStyles.HexNumber, CultureInfo.InvariantCulture);
stat.Type = (LoadingType)Enum.Parse(typeof(LoadingType), tokens[2]);
stat.StartTime = UInt64.Parse(tokens[3]);
stat.EndTime = UInt64.Parse(tokens[4]);
if (stat.EndTime < stat.StartTime && stat.Type != LoadingType.Custom)
throw new InvalidDataException(string.Format("LoadingProfiler log file corrupt: stat.EndTime ({0}) < stat.StartTime ({1}).", stat.EndTime, stat.StartTime));
stat.Cancelled = (UInt32.Parse(tokens[5]) != 0);
if (stat.Type == LoadingType.WhiteRoom)
{
stat.Profile = whiteRoomProfile;
}
else if (stat.Type == LoadingType.WaitingForLoading && stat.ObjectID == 0ul)
{
stat.Profile = waitingProfile;
}
else if (stat.Type == LoadingType.Custom)
{
CustomType customType = (CustomType)stat.ObjectID;
if (customType == CustomType.Ghost)
{
stat.Profile = ghostProfile;
}
else if (customType == CustomType.Walkthrough)
{
stat.Profile = new EventFileProfileDesc() { m_Name = string.Format("Walkthrough {0}", stat.AdditionalID), m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(stat.Profile);
}
else
{
throw new NotImplementedException(string.Format("An unrecognized CustomType was used ({0}). Please update the executable with this new CustomType.", customType));
}
}
else
{
stat.Profile = new EventFileProfileDesc() { m_Name = string.Format("{0} 0x{1:x08}{2}", stat.Type, stat.ObjectID, stat.Cancelled ? " (cancelled)" : ""), m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(stat.Profile);
}
stats.Add(stat);
line = reader.ReadLine();
}
// Create contexts.
EventFileThreadDesc loadingContext = new EventFileThreadDesc();
loadingContext.m_Name = "Loading";
loadingContext.m_ThreadID = trace.NextContextID;
loadingContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(loadingContext);
EventFileThreadDesc missionContext = new EventFileThreadDesc();
missionContext.m_Name = "Mission";
missionContext.m_ThreadID = trace.NextContextID;
missionContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(missionContext);
EventFileThreadDesc datalayerContext = new EventFileThreadDesc();
datalayerContext.m_Name = "Data Layers";
datalayerContext.m_ThreadID = trace.NextContextID;
datalayerContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(datalayerContext);
//EventFileThreadDesc worldContext = new EventFileThreadDesc();
//worldContext.m_Name = "World";
//worldContext.m_ThreadID = trace.NextContextID;;
//worldContext.m_OSThreadID = trace.NextContextID;;
//trace.Contexts.Add(worldContext);
EventFileThreadDesc whiteRoomContext = new EventFileThreadDesc();
whiteRoomContext.m_Name = "WhiteRoom";
whiteRoomContext.m_ThreadID = trace.NextContextID;
whiteRoomContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(whiteRoomContext);
EventFileThreadDesc waitingContext = new EventFileThreadDesc();
waitingContext.m_Name = "Waiting For Loading";
waitingContext.m_ThreadID = trace.NextContextID;
waitingContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(waitingContext);
// Custom contexts
EventFileThreadDesc ghostContext = new EventFileThreadDesc();
ghostContext.m_Name = "Ghost";
ghostContext.m_ThreadID = trace.NextContextID;
ghostContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(ghostContext);
EventFileThreadDesc walkthroughContext = new EventFileThreadDesc();
walkthroughContext.m_Name = "Walkthroughs";
walkthroughContext.m_ThreadID = trace.NextContextID;
walkthroughContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(walkthroughContext);
// Create events
UInt64 lastLoadingEndTime = UInt64.MaxValue;
UInt64 lastDataLayerEndTime = UInt64.MaxValue;
UInt64 lastWaitingEndTime = UInt64.MaxValue;
bool ghosting = false;
uint lastWalkthroughProfileId = uint.MaxValue;
foreach (LoadingProfilerStat stat in stats)
{
//if (stat.Type == LoadingType.World)
//{
// WriteEvent(trace.ProfileEvents, worldContext.m_ThreadID, stat.Profile.m_ProfileID, stat.StartTime, stat.EndTime);
//}
if (stat.Type == LoadingType.NonSpatialDataLayer)
{
UInt64 startTime = stat.StartTime;
if (stat.StartTime <= lastDataLayerEndTime && stat.EndTime >= lastDataLayerEndTime)
startTime = lastDataLayerEndTime;
WriteEvent(trace.ProfileEvents, datalayerContext.m_ThreadID, stat.Profile.m_ProfileID, startTime, stat.EndTime);
lastDataLayerEndTime = stat.EndTime;
}
if (stat.Type == LoadingType.WaitingForLoading)
{
UInt64 startTime = stat.StartTime;
if (stat.StartTime <= lastWaitingEndTime && stat.EndTime >= lastWaitingEndTime)
startTime = lastWaitingEndTime;
WriteEvent(trace.ProfileEvents, waitingContext.m_ThreadID, stat.Profile.m_ProfileID, startTime, stat.EndTime);
lastWaitingEndTime = stat.EndTime;
}
else if (stat.Type == LoadingType.HighRes || stat.Type == LoadingType.DataBlock || stat.Type == LoadingType.World)
{
if (!(stat.Type == LoadingType.DataBlock && stat.Cancelled))
{
UInt64 startTime = stat.StartTime;
if (stat.StartTime <= lastLoadingEndTime && stat.EndTime >= lastLoadingEndTime)
startTime = lastLoadingEndTime;
WriteEvent(trace.ProfileEvents, loadingContext.m_ThreadID, stat.Profile.m_ProfileID, startTime, stat.EndTime);
lastLoadingEndTime = stat.EndTime;
}
else
{
// Data events, for now...
trace.DataEvents.Add(new DataEvent() { m_Time = stat.StartTime, m_ContextID = loadingContext.m_ThreadID, m_Data = string.Format("Start Datablock 0x{0:x8}", stat.ObjectID) });
trace.DataEvents.Add(new DataEvent() { m_Time = stat.EndTime, m_ContextID = loadingContext.m_ThreadID, m_Data = string.Format("Cancel Datablock 0x{0:x8}", stat.ObjectID) });
}
}
else if (stat.Type == LoadingType.Mission)
{
// Data event, for now...
trace.DataEvents.Add(new DataEvent() { m_Time = stat.StartTime, m_ContextID = loadingContext.m_ThreadID, m_Data = string.Format("Start Mission 0x{0:x8}", stat.ObjectID) });
trace.DataEvents.Add(new DataEvent() { m_Time = stat.EndTime, m_ContextID = loadingContext.m_ThreadID, m_Data = string.Format("{1} Mission 0x{0:x8}", stat.ObjectID, stat.Cancelled ? "Cancel" : "End") });
}
else if (stat.Type == LoadingType.WhiteRoom)
{
WriteEvent(trace.ProfileEvents, whiteRoomContext.m_ThreadID, stat.Profile.m_ProfileID, stat.StartTime, stat.EndTime);
}
else if (stat.Type == LoadingType.Custom)
{
CustomType customType = (CustomType)stat.ObjectID;
bool startEvent = (stat.StartTime != 0);
if (customType == CustomType.Ghost)
{
if (startEvent)
WriteEventStart(trace.ProfileEvents, ghostContext.m_ThreadID, stat.Profile.m_ProfileID, stat.StartTime);
else
WriteEventEnd(trace.ProfileEvents, ghostContext.m_ThreadID, stat.Profile.m_ProfileID, stat.EndTime);
ghosting = !ghosting;
}
else if (customType == CustomType.Walkthrough)
{
// If the last walkthrough was not closed, close it.
if (lastWalkthroughProfileId != uint.MaxValue)
WriteEventEnd(trace.ProfileEvents, walkthroughContext.m_ThreadID, lastWalkthroughProfileId, stat.StartTime);
if (startEvent)
{
WriteEventStart(trace.ProfileEvents, walkthroughContext.m_ThreadID, stat.Profile.m_ProfileID, stat.StartTime);
lastWalkthroughProfileId = stat.Profile.m_ProfileID;
}
else
{
WriteEventEnd(trace.ProfileEvents, walkthroughContext.m_ThreadID, stat.Profile.m_ProfileID, stat.EndTime);
lastWalkthroughProfileId = uint.MaxValue;
}
}
}
}
if (ghosting) // Close ghosting if we were ghosting at the end of the log
WriteEventEnd(trace.ProfileEvents, ghostContext.m_ThreadID, ghostProfile.m_ProfileID, trace.ProfileEvents[trace.ProfileEvents.Count - 1].m_Time);
if (lastWalkthroughProfileId != uint.MaxValue) // Close walkthrough if it was not closed properly
WriteEventEnd(trace.ProfileEvents, walkthroughContext.m_ThreadID, lastWalkthroughProfileId, trace.ProfileEvents[trace.ProfileEvents.Count - 1].m_Time);
return 0;
}
private enum LoadingType
{
World,
Mission,
//SpatialDataLayer, // Unused, as there is no way for now to know when this is done.
NonSpatialDataLayer,
DataBlock,
HighRes,
WhiteRoom,
WaitingForLoading,
Custom,
}
private enum CustomType
{
Ghost,
Walkthrough, // Can have additional data.
COUNT
}
private struct LoadingProfilerStat
{
public ObjectID ObjectID;
public ObjectID AdditionalID;
public LoadingType Type;
public UInt64 StartTime;
public UInt64 EndTime;
public bool Cancelled;
public EventFileProfileDesc Profile;
}
#endregion
#region SoundStream logs
private static int ReadSoundStreamLog(StreamReader reader, SimplifiedTrace trace)
{
List<SoundStreamStat> sounds = new List<SoundStreamStat>();
// Read the data
string line = reader.ReadLine();
while (line != null)
{
string[] tokens = line.Split(',');
if (tokens.Length != 7)
throw new InvalidDataException(string.Format("SoundStream log file corrupt: Malformed line does not contain 7 tokens: \"{0}\"", line));
SoundStreamStat sound = new SoundStreamStat();
sound.SoundType = tokens[0] == "Bank" ? LoadSoundType.Bank : LoadSoundType.Stream;
sound.ReadOffset = UInt64.Parse(tokens[1]);
sound.ReadSize = UInt32.Parse(tokens[2]);
sound.BufferSize = UInt32.Parse(tokens[3]);
sound.FileSize = Int64.Parse(tokens[4]);
sound.StartTime = UInt64.Parse(tokens[5]);
sound.EndTime = UInt64.Parse(tokens[6]);
if (sound.StartTime > sound.EndTime)
throw new InvalidDataException(string.Format("SoundStream log file corrupt: sound.StartTime ({0}) > sound.EndTime ({1}).", sound.StartTime, sound.EndTime));
sound.Profile = new EventFileProfileDesc() { m_Name = string.Format("Sound {0} {1} {2} ({3})", sound.SoundType.ToString(), sound.ReadOffset, sound.ReadSize, sound.BufferSize), m_ProfileID = trace.NextProfileID };
trace.Profiles.Add(sound.Profile);
sounds.Add(sound);
line = reader.ReadLine();
}
// Create contexts.
EventFileThreadDesc soundContext = new EventFileThreadDesc();
soundContext.m_Name = "Sound Requests";
soundContext.m_ThreadID = trace.NextContextID;
soundContext.m_OSThreadID = trace.NextContextID;
trace.Contexts.Add(soundContext);
// Create events
if (sounds.Count > 0)
{
UInt64 currentTime = sounds[0].StartTime;
for (int i = 0; i < sounds.Count; ++i)
{
WriteEvent(trace.ProfileEvents, soundContext.m_ThreadID, sounds[i].Profile.m_ProfileID, Math.Max(currentTime, sounds[i].StartTime), sounds[i].EndTime);
currentTime = sounds[i].EndTime;
trace.DataEvents.Add(new DataEvent { m_ContextID = soundContext.m_ThreadID, m_Data = string.Format("Sound {0} {1}", sounds[i].SoundType.ToString(), sounds[i].ReadOffset), m_Time = sounds[i].StartTime });
}
}
return 0;
}
private enum LoadSoundType
{
Bank,
Stream
}
private struct SoundStreamStat
{
public LoadSoundType SoundType;
public Int64 FileSize;
public UInt64 ReadOffset;
public UInt32 ReadSize;
public UInt32 BufferSize;
public UInt64 StartTime;
public UInt64 EndTime;
public EventFileProfileDesc Profile;
}
#endregion
#region Utilities
private static void WriteEvent(List<ProfileEvent> events, UInt32 contextID, UInt32 profileId, UInt64 startTime, UInt64 endTime)
{
WriteEventStart(events, contextID, profileId, startTime);
WriteEventEnd(events, contextID, profileId, endTime);
}
private static void WriteEventStart(List<ProfileEvent> events, UInt32 contextID, UInt32 profileId, UInt64 time)
{
WriteEvent(events, contextID, profileId, time, 0 /*StartEvent*/);
}
private static void WriteEventEnd(List<ProfileEvent> events, UInt32 contextID, UInt32 profileId, UInt64 time)
{
WriteEvent(events, contextID, profileId, time, 1 /*StopEvent*/);
}
private static void WriteEvent(List<ProfileEvent> events, UInt32 contextID, UInt32 profileId, UInt64 time, uint type)
{
ProfileEvent eventStart = new ProfileEvent();
eventStart.m_ContextID = contextID;
eventStart.m_ProfileID = profileId;
eventStart.m_Type = type;
eventStart.m_Time = time;
events.Add(eventStart);
}
private static void StableSort<T>(IList<T> list, Comparison<T> comparison)
{
MergeSort.Sort(list, comparison);
}
// TODO: Use ProfileEventData and add a method to save it.
private class SimplifiedTrace
{
public List<EventFileThreadDesc> Contexts = new List<EventFileThreadDesc>();
public List<EventFileProfileDesc> Profiles = new List<EventFileProfileDesc>();
public List<ProfileEvent> ProfileEvents = new List<ProfileEvent>();
public List<DataEvent> DataEvents = new List<DataEvent>();
public UInt32 NextContextID { get { return (UInt32)Contexts.Count; } }
public UInt32 NextProfileID { get { return (UInt32)Profiles.Count; } }
public void Write(string fileName)
{
// Stable sort needed...
StableSort<ProfileEvent>(ProfileEvents, (ProfileEvent a, ProfileEvent b) => a.m_Time.CompareTo(b.m_Time));
StableSort<DataEvent>(DataEvents, (DataEvent a, DataEvent b) => a.m_Time.CompareTo(b.m_Time));
Stream stream = new FileStream(fileName, FileMode.Create, FileAccess.Write);
BinaryWriter writer = new BinaryWriter(stream);
writer.Write((UInt32)3); // Version
writer.Write((UInt32)1000000); // Frequency
byte[] descriptor = new byte[256];
descriptor.Initialize();
Encoding.ASCII.GetBytes("Loading stats").CopyTo(descriptor, 0);
writer.Write(descriptor); // Descriptor
writer.Write((UInt32)Contexts.Count); // Nb context descs
writer.Write((UInt32)Profiles.Count); // Nb profile descs
writer.Write((UInt32)0); // Nb task descs
writer.Write((UInt32)ProfileEvents.Count); // Nb profile events
writer.Write((UInt32)DataEvents.Count); // Nb data events
writer.Write((UInt32)0); // Nb frame events
writer.Write((UInt32)0); // Nb task events
writer.Write((UInt32)0); // Nb thread switch events
// Contexts
foreach (EventFileThreadDesc context in Contexts)
{
byte[] contextName = new byte[60];
contextName.Initialize();
Encoding.ASCII.GetBytes(context.m_Name, 0, Math.Min(60, context.m_Name.Length), contextName, 0);
writer.Write(contextName);
writer.Write((UInt32)context.m_ThreadID); // Context ID
writer.Write((UInt32)context.m_OSThreadID); // Thread ID
}
// Profiles
foreach (EventFileProfileDesc profile in Profiles)
{
byte[] profileName = new byte[60];
profileName.Initialize();
Encoding.ASCII.GetBytes(profile.m_Name, 0, Math.Min(60, profile.m_Name.Length), profileName, 0);
writer.Write(profileName);
writer.Write((UInt32)profile.m_ProfileID); // Profile ID
}
// Profile Events
foreach (ProfileEvent profileEvent in ProfileEvents)
{
writer.Write((UInt64)profileEvent.m_Time); // Time
writer.Write((UInt32)profileEvent.m_ProfileID); // Profile ID
writer.Write((UInt16)profileEvent.m_Type); // Type (StartEvent)
writer.Write((UInt16)profileEvent.m_ContextID); // Context ID
}
// Event data
foreach (DataEvent data in DataEvents)
{
writer.Write((UInt64)data.m_Time);
writer.Write((UInt16)data.m_ContextID);
byte[] dataStr = new byte[118];
dataStr.Initialize();
Encoding.ASCII.GetBytes(data.m_Data, 0, Math.Min(118, data.m_Data.Length), dataStr, 0);
writer.Write(dataStr);
}
writer.Close();
}
}
#endregion
}
}