Improved time tracking to keep history

Ryujinx.Profiler/InternalProfile.cs

@@ -3,6 +3,7 @@ using System.Collections.Concurrent;
 using System.Collections.Generic;
 using System.Diagnostics;
 using System.Linq;
+using System.Threading;
 
 namespace Ryujinx.Profiler
 {
@@ -14,57 +15,58 @@ namespace Ryujinx.Profiler
         private readonly object _sessionLock = new object();
         private int _sessionCounter = 0;
 
-        public InternalProfile()
+        // Cleanup thread
+        private readonly Thread _cleanupThread;
+        private bool _cleanupRunning;
+        private readonly long _history;
+
+        public InternalProfile(long history)
         {
-            Timers = new ConcurrentDictionary<ProfileConfig, TimingInfo>();
+            Timers          = new ConcurrentDictionary<ProfileConfig, TimingInfo>();
+            _history        = history;
+            _cleanupRunning = true;
+
+            // Create low priority cleanup thread, it only cleans up RAM hence the low priority
+            _cleanupThread = new Thread(CleanupLoop)
+            {
+                Priority = ThreadPriority.Lowest
+            };
+            _cleanupThread.Start();
 
             SW = new Stopwatch();
             SW.Start();
         }
 
+        private void CleanupLoop()
+        {
+            while (_cleanupRunning)
+            {
+                foreach (var timer in Timers)
+                {
+                    timer.Value.Cleanup(SW.ElapsedTicks - _history);
+                }
+
+                // No need to run too often
+                Thread.Sleep(50);
+            }
+        }
+
         public void BeginProfile(ProfileConfig config)
         {
-            long timestamp = SW.ElapsedTicks;
-
-            Timers.AddOrUpdate(config,
-                (c) => CreateTimer(timestamp),
-                ((s, info) =>
-                {
-                    info.BeginTime = timestamp;
-                    return info;
-                }));
+            Timers.GetOrAdd(config, profileConfig => new TimingInfo()).Begin(SW.ElapsedTicks);
         }
 
         public void EndProfile(ProfileConfig config)
         {
-            long timestamp = SW.ElapsedTicks;
-
-            Timers.AddOrUpdate(config,
-                (c => new TimingInfo()),
-                ((s, time) => UpdateTimer(time, timestamp)));
-        }
-
-        private TimingInfo CreateTimer(long timestamp)
-        {
-            return new TimingInfo()
+            if (Timers.TryGetValue(config, out var timingInfo))
             {
-                BeginTime = timestamp,
-                LastTime = 0,
-                Count = 0,
-                Instant = 0,
-                InstantCount = 0,
-            };
-        }
-
-        private TimingInfo UpdateTimer(TimingInfo time, long timestamp)
-        {
-            time.Count++;
-            time.InstantCount++;
-            time.LastTime = timestamp - time.BeginTime;
-            time.TotalTime += time.LastTime;
-            time.Instant += time.LastTime;
-
-            return time;
+                timingInfo.End(SW.ElapsedTicks);
+            }
+            else
+            {
+                // Throw exception if config isn't already being tracked
+                throw new Exception($"Profiler end called before begin for {config.Tag}");
+            }
         }
 
         public string GetSession()
@@ -94,8 +96,8 @@ namespace Ryujinx.Profiler
                 TimingInfo value, prevValue;
                 if (Timers.TryGetValue(key, out value))
                 {
-                    prevValue = value;
-                    value.Instant = 0;
+                    prevValue          = value;
+                    value.Instant      = 0;
                     value.InstantCount = 0;
                     Timers.TryUpdate(key, value, prevValue);
                 }
@@ -103,5 +105,11 @@ namespace Ryujinx.Profiler
 
             return outDict;
         }
+
+        public void Dispose()
+        {
+            _cleanupRunning = false;
+            _cleanupThread.Join();
+        }
     }
 }

Ryujinx.Profiler/Profile.cs

@@ -16,7 +16,8 @@ namespace Ryujinx.Profiler
                 return false;
 
             if (_profileInstance == null)
-                _profileInstance = new InternalProfile();
+                _profileInstance = new InternalProfile(_settings.History);
+
             return true;
         }
 
@@ -32,6 +33,8 @@ namespace Ryujinx.Profiler
 
             if (_settings.FileDumpEnabled)
                 DumpProfile.ToFile(_settings.DumpLocation, _profileInstance);
+
+            _profileInstance.Dispose();
         }
 
         public static void Begin(ProfileConfig config)
@@ -74,6 +77,11 @@ namespace Ryujinx.Profiler
             return (((double)ticks) / Stopwatch.Frequency) * 1000.0;
         }
 
+        public static long ConvertSecondsToTicks(double seconds)
+        {
+            return (long)(seconds * Stopwatch.Frequency);
+        }
+
         public static Dictionary<ProfileConfig, TimingInfo> GetProfilingData()
         {
             if (!ProfilingEnabled())

Ryujinx.Profiler/Settings.cs

@@ -11,5 +11,8 @@ namespace Ryujinx.Profiler
         public bool   FileDumpEnabled = false;
         public string DumpLocation    = "";
         public float  UpdateRate      = 0.1f;
+
+        // 19531225 = 5 seconds in ticks
+        public long   History         = 19531225;
     }
 }

Ryujinx.Profiler/TimingInfo.cs

@@ -1,10 +1,17 @@
-namespace Ryujinx.Profiler
+using System;
+using System.Collections.Generic;
+
+namespace Ryujinx.Profiler
 {
-    public struct TimingInfo
+    public struct Timestamp
+    {
+        public long BeginTime;
+        public long EndTime;
+    }
+
+    public class TimingInfo
     {
         // Timestamps
-        public long BeginTime;
-        public long LastTime;
         public long TotalTime;
         public long Instant;
 
@@ -14,5 +21,101 @@
         
         // Work out average
         public long AverageTime => (Count == 0) ? -1 : TotalTime / Count;
+
+        // Timestamp collection
+        public List<Timestamp> Timestamps;
+        private readonly object timestampLock = new object();
+        private Timestamp currentTimestamp;
+
+        // Depth of current timer,
+        // each begin call increments and each end call decrements
+        private int depth;
+        
+
+        public TimingInfo()
+        {
+            Timestamps = new List<Timestamp>();
+            depth      = 0;
+        }
+
+        public void Begin(long beginTime)
+        {
+            lock (timestampLock)
+            {
+                // Finish current timestamp if already running
+                if (depth > 0)
+                {
+                    EndUnsafe(beginTime);
+                }
+
+                BeginUnsafe(beginTime);
+                depth++;
+            }
+        }
+
+        private void BeginUnsafe(long beginTime)
+        {
+            currentTimestamp.BeginTime = beginTime;
+            currentTimestamp.EndTime   = -1;
+        }
+
+        public void End(long endTime)
+        {
+            lock (timestampLock)
+            {
+                depth--;
+
+                if (depth < 0)
+                {
+                    throw new Exception("Timing info end called without corresponding begin");
+                }
+
+                EndUnsafe(endTime);
+
+                // Still have others using this timing info so recreate start for them
+                if (depth > 0)
+                {
+                    BeginUnsafe(endTime);
+                }
+            }
+        }
+
+        private void EndUnsafe(long endTime)
+        {
+            currentTimestamp.EndTime = endTime;
+            Timestamps.Add(currentTimestamp);
+
+            var delta  = currentTimestamp.EndTime - currentTimestamp.BeginTime;
+            TotalTime += delta;
+            Instant   += delta;
+
+            Count++;
+            InstantCount++;
+        }
+
+        // Remove any timestamps before given timestamp to free memory
+        public void Cleanup(long before)
+        {
+            lock (timestampLock)
+            {
+                int toRemove = 0;
+
+                for (int i = 0; i < Timestamps.Count; i++)
+                {
+                    if (Timestamps[i].EndTime < before)
+                    {
+                        toRemove++;
+                    }
+                    else
+                    {
+                        // Assume timestamps are in chronological order so no more need to be removed
+                        break;
+                    }
+                }
+
+                if (toRemove > 0)
+                    Timestamps.RemoveRange(0, toRemove);
+            }
+        }
     }
 }

Ryujinx/Config.cs

@@ -73,6 +73,7 @@ namespace Ryujinx
                 FileDumpEnabled = profilePath != "",
                 DumpLocation    = profilePath,
                 UpdateRate      = 1.0f / Convert.ToSingle(parser.Value("Profiling_Update_Rate")),
+                History         = Profile.ConvertSecondsToTicks(Convert.ToDouble(parser.Value("Profiling_History"))),
             });
 
             SystemLanguage SetLanguage = Enum.Parse<SystemLanguage>(parser.Value("System_Language"));

Ryujinx/Program.cs

@@ -5,6 +5,7 @@ using Ryujinx.Graphics.Gal.OpenGL;
 using Ryujinx.HLE;
 using System;
 using System.IO;
+using Ryujinx.Profiler;
 
 namespace Ryujinx
 {
@@ -80,6 +81,8 @@ namespace Ryujinx
             {
                 screen.MainLoop();
 
+                Profile.FinishProfiling();
+
                 device.Dispose();
             }
 

Ryujinx/Ryujinx.conf

@@ -31,6 +31,9 @@ Profile_Dump_Path =
 #Update rate for profiler UI, in hertz
 Profiling_Update_Rate = 4
 
+#Set how long to keep profiling data in seconds, reduce if profiling is taking too much RAM
+Profiling_History = 5
+
 #System Language list: https://gist.github.com/HorrorTroll/b6e4a88d774c3c9b3bdf54d79a7ca43b
 #Change System Language
 System_Language = AmericanEnglish