From cbef04b80123115bfd6f523d6ce1f8f09e3f10bb Mon Sep 17 00:00:00 2001 From: fsfod Date: Fri, 12 Apr 2019 07:20:56 +0100 Subject: [PATCH] Add some tracking of slow frames and allow navigating to the in the frame detail view Auto expand and select the node with the largest ExclusiveTime in the mainthread when navigating to a slow frame in the frame detail view. --- src/LibPerfLog/LibPerflog.csproj | 3 + src/LibPerfLog/ProfileFrame.cs | 22 ++++- src/LibPerfLog/ProfileLog.cs | 63 +++++++++++--- src/LibPerfLog/ProfileThread.cs | 30 +++++++ src/LibPerfLog/packages.config | 1 + src/PerfAnalyzer/FrameDetailView.xaml | 38 +++++--- src/PerfAnalyzer/FrameDetailViewModel.cs | 105 ++++++++++++++++++++++- src/PerfAnalyzer/FrameTimeView.xaml | 7 +- 8 files changed, 239 insertions(+), 30 deletions(-) diff --git a/src/LibPerfLog/LibPerflog.csproj b/src/LibPerfLog/LibPerflog.csproj index 6a8753b..40da4e8 100644 --- a/src/LibPerfLog/LibPerflog.csproj +++ b/src/LibPerfLog/LibPerflog.csproj @@ -33,6 +33,9 @@ true + + ..\..\packages\LinqStatistics.2.2.0\lib\net40\LinqStatistics.dll + ..\..\packages\morelinq.2.10.0\lib\net40\MoreLinq.dll diff --git a/src/LibPerfLog/ProfileFrame.cs b/src/LibPerfLog/ProfileFrame.cs index 59960ff..44fb6f8 100644 --- a/src/LibPerfLog/ProfileFrame.cs +++ b/src/LibPerfLog/ProfileFrame.cs @@ -30,7 +30,7 @@ public class ProfileFrame { public uint GCCount { get; private set; } public int MaxDepth { get; internal set; } - public uint FrameIndex { get; private set; } + public int FrameIndex { get; private set; } public ProfileLog Owner { get; private set; } public ProfileFrame PrevFrame => FrameIndex > 0 ? Owner.Frames[(int)FrameIndex - 1] : null; public ProfileFrame NextFrame => FrameIndex < Owner.Frames.Count ? Owner.Frames[(int)FrameIndex +1] : null; @@ -38,6 +38,7 @@ public class ProfileFrame { public double TotalTimeMS => TotalTime * 1000000; public double StartTimeMS => StartTime / 1000.0; public double EndTimeMS => EndTime / 1000.0; + public bool IsSlowFrame => MainThread.TimeMs > Owner.SlowFrameThreshold; public uint GameTime => Sections[(int)PSectionId.Game].Time; public double GameRatio => GameTime / TotalTimeMS; @@ -48,7 +49,7 @@ public class ProfileFrame { public uint RenderingTime => Sections[(int)PSectionId.Rendering].Time; public double RenderingRatio => RenderingTime / TotalTimeMS; - public ProfileFrame(ProfileLog owner, uint frameIndex, long startTime, ProfileSection[] sections) { + public ProfileFrame(ProfileLog owner, int frameIndex, long startTime, ProfileSection[] sections) { Owner = owner; FrameIndex = frameIndex; EndTime = startTime; @@ -179,6 +180,7 @@ private void SubTime(int index, int[] depthToParent) { } private ProfileThread AddThread(int start) { + Debug.Assert(Calls[start].ppid == Owner.Threadppid); int entryPoint = start + 1; int ownerId, depth; @@ -254,6 +256,22 @@ public IEnumerable GetChildNodesOfNode(int nodeIndex) { } } + + public IEnumerable GetNodeParentIndexes(int nodeIndex, int limit = -1) { + int curDepth = Calls[nodeIndex].Depth; + + for (int i = nodeIndex - 1; i >= 0; i--) { + if (Calls[i].Depth == 0 || (limit >= 0 && i <= limit)) { + yield break; + } + + if (Calls[i].Depth < curDepth) { + curDepth = Calls[i].Depth; + yield return i; + } + } + } + public IEnumerable GetChildNodesIndexs(int nodeIndex, int minDepth = -1) { minDepth = minDepth != -1 ? minDepth : Calls[nodeIndex].Depth; diff --git a/src/LibPerfLog/ProfileLog.cs b/src/LibPerfLog/ProfileLog.cs index d5aad21..71490a1 100644 --- a/src/LibPerfLog/ProfileLog.cs +++ b/src/LibPerfLog/ProfileLog.cs @@ -6,6 +6,7 @@ using System.Text; using System.Threading.Tasks; using MoreLinq; +using LinqStatistics; namespace PerformanceLog { @@ -320,21 +321,56 @@ internal void Load(string filePath) { NodeStats = GetStatsForRange(0, Frames.Count); NodeStatsLookup = NodeStats.ToDictionary(n => n.Id, n => n); - /* - cppNames = ppLookup.Keys.Where(k => k.Contains("::")).ToHashSet(); - - var times = Frames.Select(f => f.TotalTime).OrderByDescending(i => i).ToArray(); + var sortedFrames = Frames. + OrderByDescending(f => f.MainThread.Time). + ToArray(); + var avgtime = sortedFrames. + Skip((int)(sortedFrames.Length * 0.1)). + Select(f => f.MainThread.TimeMs). + Average(); + // Treat any frame that is more than 80% slower than the average of 90 percentile frame time as a slow frame + SlowFrameThreshold = avgtime * 1.8; + + SlowFrames = Frames. + Skip(2). // Skip the first two frames that could be the game still loading in or something + Where(f => f.MainThread.TimeMs > SlowFrameThreshold). + ToList(); - var maxFrame = Frames.MaxBy(f => f.TotalTime); - // var avg = Frames.Where(f => f.TotalTime > 180).Average(f => f.TotalTime); - - var threadList = Frames.SelectMany(f => f.Threads).ToList(); + return; + } - var threads = threadList.GroupBy(t => t.Name).ToLookup(g => g.Key, g => g?.ToList()); - */ + public int PrevSlowFrame(int startIndex) { + if (startIndex == 0 || SlowFrames.Count == 0 || startIndex >= Frames.Count - 1) { + return -1; + } + if (startIndex <= SlowFrames[0].FrameIndex) { + return -1; + } + Debug.Assert(startIndex <= Frames.Count); + var index = SlowFrames.BinarySearch(startIndex-1, f => f.FrameIndex); + if (index < 0) { + index = -index; + } + if (SlowFrames[index].FrameIndex == startIndex) { + index--; + } + return index >= 0 ? SlowFrames[index].FrameIndex : -1; + } + public int NextSlowFrame(int startIndex) { + if (SlowFrames.Count == 0 || startIndex >= Frames.Count-1) { + return -1; + } + if (startIndex >= SlowFrames.Last().FrameIndex) { + return -1; + } + Debug.Assert(startIndex <= Frames.Count); + var index = SlowFrames.BinarySearch(startIndex, f => f.FrameIndex); + if (index < 0) { + index = -index; + } - return; + return SlowFrames[index + 1].FrameIndex; } private void ParseLoop() { @@ -426,7 +462,7 @@ private void ParseLoop() { } private bool skippedFirstFrame = false; - uint frameCount = 0; + int frameCount = 0; long prevTime = 0; private ProfileFrame _currentframe; @@ -860,6 +896,9 @@ public List GetNodeFrameStats(IList nodeIds) { //Returns duration of log in seconds public double Duration => ((Frames.Last().EndTimeMS - Frames.First().EndTimeMS) / 1000); + public double SlowFrameThreshold { get; private set; } = 10.0; + public List SlowFrames { get; private set; } + public override string ToString() { return $"{Path.GetFileName(FilePath)} Frames: {Frames.Count} Time: {Duration} seconds"; } diff --git a/src/LibPerfLog/ProfileThread.cs b/src/LibPerfLog/ProfileThread.cs index f8a76e2..b23605b 100644 --- a/src/LibPerfLog/ProfileThread.cs +++ b/src/LibPerfLog/ProfileThread.cs @@ -67,6 +67,10 @@ public CallRecord GetNodeWithId(int id) { return index != -1 ? Frame.Calls[index] : default(CallRecord); } + public IEnumerable GetNodeParentIndexes(int nodeIndex) { + return Frame.GetNodeParentIndexes(nodeIndex, StartIndex); + } + public string NodesString { get { return Frame.GetNodeString(StartIndex, NodeCount != -1 ? NodeCount : Frame.Calls.Length); @@ -77,6 +81,32 @@ public override string ToString() { return $"Thread({Name}) Time: {TimeMs:F3}ms Nodes: {NodeCount}"; } + public int PeakExclusiveIndex() { + uint peak = 0; + int index = -1; + var nodes = Frame.Calls; + for (int i = StartIndex; i < StartIndex + NodeCount; i++) { + if (nodes[i].ExclusiveTime > peak) { + index = i; + peak = nodes[i].ExclusiveTime; + } + } + return index; + } + + public int PeakInclusiveIndex() { + uint peak = 0; + int index = -1; + var nodes = Frame.Calls; + for (int i = StartIndex; i < StartIndex + NodeCount; i++) { + if (nodes[i].Time > peak) { + index = i; + peak = nodes[i].Time; + } + } + return index; + } + internal void AddIdleTime(uint time, uint count) { IdleTime += time; IdleCount += count; diff --git a/src/LibPerfLog/packages.config b/src/LibPerfLog/packages.config index e2c4430..9ab2975 100644 --- a/src/LibPerfLog/packages.config +++ b/src/LibPerfLog/packages.config @@ -1,5 +1,6 @@  + \ No newline at end of file diff --git a/src/PerfAnalyzer/FrameDetailView.xaml b/src/PerfAnalyzer/FrameDetailView.xaml index d28a547..134d8e4 100644 --- a/src/PerfAnalyzer/FrameDetailView.xaml +++ b/src/PerfAnalyzer/FrameDetailView.xaml @@ -10,11 +10,12 @@ mc:Ignorable="d" MinHeight="500" MinWidth="705"> - + - + + - -