Add some tracking of slow frames and allow navigating to the in the f…

…rame 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.
NS2CDT · Apr 12, 2019 · cbef04b · cbef04b
1 parent 8ec3f16
commit cbef04b
Show file tree

Hide file tree

Showing 8 changed files with 239 additions and 30 deletions.
diff --git a/src/LibPerfLog/LibPerflog.csproj b/src/LibPerfLog/LibPerflog.csproj
@@ -33,6 +33,9 @@
     <AllowUnsafeBlocks>true</AllowUnsafeBlocks>
   </PropertyGroup>
   <ItemGroup>
+    <Reference Include="LinqStatistics, Version=2.2.0.0, Culture=neutral, processorArchitecture=MSIL">
+      <HintPath>..\..\packages\LinqStatistics.2.2.0\lib\net40\LinqStatistics.dll</HintPath>
+    </Reference>
     <Reference Include="MoreLinq, Version=2.10.21623.0, Culture=neutral, PublicKeyToken=384d532d7e88985d, processorArchitecture=MSIL">
       <HintPath>..\..\packages\morelinq.2.10.0\lib\net40\MoreLinq.dll</HintPath>
     </Reference>

diff --git a/src/LibPerfLog/ProfileFrame.cs b/src/LibPerfLog/ProfileFrame.cs
@@ -30,14 +30,15 @@ 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;
 
     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<CallRecord> GetChildNodesOfNode(int nodeIndex) {
       }
     }
 
+
+    public IEnumerable<int> 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<int> 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
@@ -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<NodeFrameEntry[]> GetNodeFrameStats(IList<int> 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<ProfileFrame> 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
@@ -67,6 +67,10 @@ public CallRecord GetNodeWithId(int id) {
       return index != -1 ? Frame.Calls[index] : default(CallRecord);
     }
 
+    public IEnumerable<int> 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
@@ -1,5 +1,6 @@
 <?xml version="1.0" encoding="utf-8"?>
 <packages>
+  <package id="LinqStatistics" version="2.2.0" targetFramework="net461" />
   <package id="morelinq" version="2.10.0" targetFramework="net461" />
   <package id="System.ValueTuple" version="4.4.0" targetFramework="net461" />
 </packages>
diff --git a/src/PerfAnalyzer/FrameDetailView.xaml b/src/PerfAnalyzer/FrameDetailView.xaml
@@ -10,11 +10,12 @@
              mc:Ignorable="d"
              MinHeight="500"
              MinWidth="705">
-  <Grid Margin="10,0,10,10" VerticalAlignment="Stretch">
+  <Grid Margin="10,10,10,10" VerticalAlignment="Stretch">
     <Grid.RowDefinitions>
-      <RowDefinition Height="60"/>
+      <RowDefinition Height="30" />
       <RowDefinition Height="*" MinHeight="200"/>
     </Grid.RowDefinitions>
+
     <treeview:SharpTreeView x:Name="CallNodeList" Margin="10,17,10,10"
                                 VerticalAlignment="Stretch"
                                 HorizontalAlignment="Stretch"
@@ -46,16 +47,29 @@
       </ListView.View>
     </treeview:SharpTreeView>
 
-    <StackPanel HorizontalAlignment="Left" Height="27" Margin="10,27,0,0" VerticalAlignment="Top" Width="242" Orientation="Horizontal" Grid.Row="0">
-      <Button x:Name="GotoPrevFrame" Content="Prev" Width="40" HorizontalAlignment="Center"/>
-      <Button x:Name="GotoNextFrame" Content="Next" Width="40" HorizontalAlignment="Center"/>
-      <Label x:Name="label" Content="Frame:"/>
-      <TextBox x:Name="FrameId" TextWrapping="Wrap" Text="TextBox" Width="102" HorizontalAlignment="Right" Margin="5,0,0,0"
+    <Grid VerticalAlignment="Stretch">
+      <Grid.ColumnDefinitions>
+        <ColumnDefinition />
+        <ColumnDefinition />
+        <ColumnDefinition Width="*"/>
+      </Grid.ColumnDefinitions>
+
+      <StackPanel HorizontalAlignment="Left" Height="27" Margin="10,0,0,0" VerticalAlignment="Top"  Orientation="Horizontal" Grid.Column="0">
+        <Button x:Name="GotoPrevFrame" Content="Prev" Width="40" HorizontalAlignment="Center" Margin="0,0,2,0"/>
+        <Button x:Name="GotoNextFrame" Content="Next" Width="40" HorizontalAlignment="Center"/>
+        <Label x:Name="label" Content="Frame:" Margin="5,0,0,0"/>
+        <TextBox x:Name="FrameId" TextWrapping="Wrap" Text="TextBox" Width="102" HorizontalAlignment="Right" Margin="5,0,0,0"
                cal:Message.Attach="[Event MouseWheel] = [Action ScrollFrames($this, $eventArgs)]"/>
-    </StackPanel>
-    <StackPanel HorizontalAlignment="Left" Height="27" Margin="323,27,0,0" VerticalAlignment="Top" Width="154" Orientation="Horizontal" Grid.Row="0">
-      <Button x:Name="CollapseAll" Content="Collapse All" Width="75" HorizontalAlignment="Left" Height="27"/>
-      <Button x:Name="ExpandAll" Content="Expand All" Width="75"  Height="27"/>
-    </StackPanel>
+      </StackPanel>
+      <StackPanel HorizontalAlignment="Left" Height="27" Margin="0,0,0,0" VerticalAlignment="Top" Orientation="Horizontal" Grid.Column="1" Grid.ColumnSpan="2">
+        <Label Content="Slow Frames:" Margin="10,0,0,0" />
+        <Button x:Name="GotoPrevSlowFrame" Content="Prev" Width="35" HorizontalAlignment="Center" Margin="0,0,2,0" />
+        <Button x:Name="GotoNextSlowFrame" Content="Next" Width="35" HorizontalAlignment="Center" />
+      </StackPanel>
+      <StackPanel HorizontalAlignment="Left" Height="27"  VerticalAlignment="Top" Width="154" Orientation="Horizontal" Grid.Column="2">
+        <Button x:Name="CollapseAll" Content="Collapse All" Width="75" HorizontalAlignment="Left" Height="27"/>
+        <Button x:Name="ExpandAll" Content="Expand All" Width="75"  Height="27"/>
+      </StackPanel>
+    </Grid>
   </Grid>
 </UserControl>