Remove SerilogTimings and add a benchmark that fit our needs.

Vocaluxe/Base/CGraphics.cs

@@ -21,7 +21,6 @@ using System.Diagnostics;
 using System.Drawing;
 using System.Windows.Forms;
 using Serilog.Events;
-using SerilogTimings;
 using Vocaluxe.Base.Fonts;
 using Vocaluxe.Base.ThemeSystem;
 using Vocaluxe.Screens;
@@ -65,7 +64,7 @@ namespace Vocaluxe.Base
         {
             // Add Screens, must be the same order as in EScreens!
             CLog.Information("Build Screen List");
-            using (Operation.At(LogEventLevel.Information).Time("Build Screen List"))
+            using (CBenchmark.Time("Build Screen List"))
             {
                 _Screens.Add(new CScreenTest());
                 _Screens.Add(new CScreenLoad());
@@ -102,7 +101,7 @@ namespace Vocaluxe.Base
             ZOffset = 0f;
 
             CLog.Information("Load Theme");
-            using (Operation.At(LogEventLevel.Information).Time("Load Theme"))
+            using (CBenchmark.Time("Load Theme"))
             {
                 LoadTheme();
             }
@@ -123,7 +122,7 @@ namespace Vocaluxe.Base
             for (int i = 0; i < _Screens.Count; i++)
             {
                 CLog.Information("Load Theme " + Enum.GetNames(typeof(EScreen))[i]);
-                using (Operation.At(LogEventLevel.Information).Time("Load Theme " + Enum.GetNames(typeof(EScreen))[i]))
+                using (CBenchmark.Time("Load Theme " + Enum.GetNames(typeof(EScreen))[i]))
                 {
                     _Screens[i].Init();
                     _Screens[i].LoadTheme(CThemes.GetThemeScreensPath(_Screens[i].PartyModeID));

Vocaluxe/Base/CSongs.cs

@@ -22,8 +22,6 @@ using System.Linq;
 using System.Threading;
 using System.IO;
 using System.Threading.Tasks;
-using Serilog.Events;
-using SerilogTimings;
 using VocaluxeLib;
 using VocaluxeLib.Log;
 using VocaluxeLib.Songs;
@@ -337,7 +335,7 @@ namespace Vocaluxe.Base
         public static void LoadSongs()
         {
             CLog.Information("Load Songs");
-            using (Operation.At(LogEventLevel.Information).Time("Load Songs"))
+            using (CBenchmark.Time("Load Songs"))
             {
                 SongsLoaded = false;
                 _Songs.Clear();
@@ -345,7 +343,7 @@ namespace Vocaluxe.Base
                 var files = new List<string>();
 
                 CLog.Information("List Songs");
-                using (Operation.At(LogEventLevel.Information).Time("List Songs"))
+                using (CBenchmark.Time("List Songs"))
                 {
                     
                     foreach (string p in CConfig.SongFolders)
@@ -360,7 +358,7 @@ namespace Vocaluxe.Base
                 }
 
                 CLog.Information("Read TXTs");
-                using (Operation.At(LogEventLevel.Information).Time("Read TXTs"))
+                using (CBenchmark.Time("Read TXTs"))
                 {
                     foreach (string file in files)
                     {
@@ -374,7 +372,7 @@ namespace Vocaluxe.Base
                 }
 
                 CLog.Information("Sort Songs");
-                using (Operation.At(LogEventLevel.Information).Time("Sorted Songs"))
+                using (CBenchmark.Time("Sorted Songs"))
                 {
                     Sorter.SongSorting = CConfig.Config.Game.SongSorting;
                     Sorter.IgnoreArticles = CConfig.Config.Game.IgnoreArticles;
@@ -411,7 +409,7 @@ namespace Vocaluxe.Base
         private static void _LoadCovers()
         {
             CLog.Information("Load Covers");
-            using (Operation.At(LogEventLevel.Information).Time("Loaded Covers"))
+            using (CBenchmark.Time("Loaded Covers"))
             {
                 int songCount = _Songs.Count;
                 AutoResetEvent ev = new AutoResetEvent(songCount == 0);

Vocaluxe/Base/Fonts/CFonts.cs

@@ -21,8 +21,6 @@ using System.Diagnostics;
 using System.Drawing;
 using System.IO;
 using System.Linq;
-using Serilog.Events;
-using SerilogTimings;
 using VocaluxeLib;
 using VocaluxeLib.Log;
 using VocaluxeLib.Menu;
@@ -292,7 +290,7 @@ namespace Vocaluxe.Base.Fonts
             }
 
             CLog.Information("Build Glyphs");
-            using (Operation.At(LogEventLevel.Information).Time("Build Glyphs"))
+            using (CBenchmark.Time("Build Glyphs"))
             {
                 _BuildGlyphs();
             }

Vocaluxe/Program.cs

@@ -24,8 +24,6 @@ using System.Runtime.CompilerServices;
 using System.Runtime.ExceptionServices;
 using System.Threading;
 using System.Windows.Forms;
-using Serilog.Events;
-using SerilogTimings;
 using Vocaluxe.Base;
 using Vocaluxe.Base.Fonts;
 using Vocaluxe.Base.Server;
@@ -106,14 +104,14 @@ namespace Vocaluxe
                 CProgrammHelper.Init();
 
                 CLog.Information("Init Program");
-                using (Operation.At(LogEventLevel.Information).Time("Init Program"))
+                using (CBenchmark.Time("Init Program"))
                 {
                     CMain.Init();
                     Application.DoEvents();
 
                     // Init Language
                     CLog.Information("Init Language");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Language"))
+                    using (CBenchmark.Time("Init Language"))
                     {
                         if (!CLanguage.Init())
                             throw new CLoadingException("Language");
@@ -123,7 +121,7 @@ namespace Vocaluxe
 
                     // load config
                     CLog.Information("Init Config");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Config"))
+                    using (CBenchmark.Time("Init Config"))
                     {
                         CConfig.LoadCommandLineParams(args);
                         CConfig.UseCommandLineParamsBefore();
@@ -139,7 +137,7 @@ namespace Vocaluxe
 
                     // Init Draw
                     CLog.Information("Init Draw");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Draw"))
+                    using (CBenchmark.Time("Init Draw"))
                     {
                         if (!CDraw.Init())
                             throw new CLoadingException("drawing");
@@ -149,7 +147,7 @@ namespace Vocaluxe
 
                     // Init Playback
                     CLog.Information("Init Playback");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Playback"))
+                    using (CBenchmark.Time("Init Playback"))
                     {
                         if (!CSound.Init())
                             throw new CLoadingException("playback");
@@ -159,7 +157,7 @@ namespace Vocaluxe
 
                     // Init Record
                     CLog.Information("Init Record");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Record"))
+                    using (CBenchmark.Time("Init Record"))
                     {
                         if (!CRecord.Init())
                             throw new CLoadingException("record");
@@ -169,7 +167,7 @@ namespace Vocaluxe
 
                     // Init VideoDecoder
                     CLog.Information("Init Videodecoder");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Videodecoder"))
+                    using (CBenchmark.Time("Init Videodecoder"))
                     {
                         if (!CVideo.Init())
                             throw new CLoadingException("video");
@@ -179,7 +177,7 @@ namespace Vocaluxe
 
                     // Init Database
                     CLog.Information("Init Database");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Database"))
+                    using (CBenchmark.Time("Init Database"))
                     {
                         if (!CDataBase.Init())
                             throw new CLoadingException("database");
@@ -189,7 +187,7 @@ namespace Vocaluxe
 
                     //Init Webcam
                     CLog.Information("Init Webcam");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Webcam"))
+                    using (CBenchmark.Time("Init Webcam"))
                     {
                         if (!CWebcam.Init())
                             throw new CLoadingException("webcam");
@@ -199,7 +197,7 @@ namespace Vocaluxe
 
                     // Init Background Music
                     CLog.Information("Init Background Music");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Background Music"))
+                    using (CBenchmark.Time("Init Background Music"))
                     {
                         CBackgroundMusic.Init();
                     }
@@ -208,7 +206,7 @@ namespace Vocaluxe
 
                     // Init Profiles
                     CLog.Information("Init Profiles");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Profiles"))
+                    using (CBenchmark.Time("Init Profiles"))
                     {
                         CProfiles.Init();
                     }
@@ -217,7 +215,7 @@ namespace Vocaluxe
 
                     // Init Fonts
                     CLog.Information("Init Fonts");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Fonts"))
+                    using (CBenchmark.Time("Init Fonts"))
                     {
                         if (!CFonts.Init())
                             throw new CLoadingException("fonts");
@@ -227,14 +225,14 @@ namespace Vocaluxe
 
                     // Theme System
                     CLog.Information("Init Theme");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Theme"))
+                    using (CBenchmark.Time("Init Theme"))
                     {
                         if (!CThemes.Init())
                             throw new CLoadingException("theme");
                     }
 
                     CLog.Information("Load Theme");
-                    using (Operation.At(LogEventLevel.Information).Time("Load Theme"))
+                    using (CBenchmark.Time("Load Theme"))
                     {
                         CThemes.Load();
                     }
@@ -243,7 +241,7 @@ namespace Vocaluxe
 
                     // Load Cover
                     CLog.Information("Init Cover");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Cover"))
+                    using (CBenchmark.Time("Init Cover"))
                     {
                         if (!CCover.Init())
                             throw new CLoadingException("covertheme");
@@ -253,7 +251,7 @@ namespace Vocaluxe
 
                     // Init Screens
                     CLog.Information("Init Screens");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Screens"))
+                    using (CBenchmark.Time("Init Screens"))
                     {
                         CGraphics.Init();
                     }
@@ -262,7 +260,7 @@ namespace Vocaluxe
 
                     // Init Server
                     CLog.Information("Init Server");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Server"))
+                    using (CBenchmark.Time("Init Server"))
                     {
                         CVocaluxeServer.Init();
                     }
@@ -271,7 +269,7 @@ namespace Vocaluxe
 
                     // Init Input
                     CLog.Information("Init Input");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Input"))
+                    using (CBenchmark.Time("Init Input"))
                     {
                         CController.Init();
                         CController.Connect();
@@ -281,7 +279,7 @@ namespace Vocaluxe
 
                     // Init Game;
                     CLog.Information("Init Game");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Game"))
+                    using (CBenchmark.Time("Init Game"))
                     {
                         CGame.Init();
                         CProfiles.Update();
@@ -292,7 +290,7 @@ namespace Vocaluxe
 
                     // Init Party Modes;
                     CLog.Information("Init Party Modes");
-                    using (Operation.At(LogEventLevel.Information).Time("Init Party Modes"))
+                    using (CBenchmark.Time("Init Party Modes"))
                     {
                         if (!CParty.Init())
                             throw new CLoadingException("Party Modes");

Vocaluxe/Screens/CScreenLoad.cs

@@ -18,8 +18,6 @@
 using System;
 using System.Threading;
 using System.Windows.Forms;
-using Serilog.Events;
-using SerilogTimings;
 using Vocaluxe.Base;
 using VocaluxeLib;
 using VocaluxeLib.Log;
@@ -130,7 +128,7 @@ namespace Vocaluxe.Screens
             }
 
             CLog.Information("Load Songs Full");
-            _TimerLoadSongsFull = Operation.At(LogEventLevel.Information).Time("Loaded Songs Full");
+            _TimerLoadSongsFull = CBenchmark.Time("Loaded Songs Full");
             
             _SongLoaderThread = new Thread(CSongs.LoadSongs) {Name = "SongLoader", IsBackground = true};
             _SongLoaderThread.Start();
@@ -189,7 +187,7 @@ namespace Vocaluxe.Screens
 
             //Init Playlists
             CLog.Information("Init Playlists");
-            using (Operation.At(LogEventLevel.Information).Time("Init Playlists"))
+            using (CBenchmark.Time("Init Playlists"))
             {
                 CPlaylists.Init();
             }

Vocaluxe/Vocaluxe.csproj

@@ -183,10 +183,6 @@
       <HintPath>..\packages\Serilog.Sinks.TextWriter.2.1.0\lib\net45\Serilog.Sinks.TextWriter.dll</HintPath>
       <Private>True</Private>
     </Reference>
-    <Reference Include="SerilogTimings, Version=2.2.0.0, Culture=neutral, PublicKeyToken=ea6fc7d88906f03a, processorArchitecture=MSIL">
-      <HintPath>..\packages\SerilogTimings.2.2.0\lib\net45\SerilogTimings.dll</HintPath>
-      <Private>True</Private>
-    </Reference>
     <Reference Include="System" />
     <Reference Include="System.Data" />
     <Reference Include="System.Drawing" />

Vocaluxe/packages.config

@@ -6,7 +6,6 @@
   <package id="Serilog.Sinks.Console" version="3.1.1" targetFramework="net471" />
   <package id="Serilog.Sinks.File" version="4.0.0" targetFramework="net471" />
   <package id="Serilog.Sinks.TextWriter" version="2.1.0" targetFramework="net471" />
-  <package id="SerilogTimings" version="2.2.0" targetFramework="net471" />
   <package id="vocaluxe.dependencies" version="1.0.11" targetFramework="net40" />
   <package id="vocaluxe.dependencies.acinerella" version="1.0.5" targetFramework="net40" />
   <package id="vocaluxe.dependencies.aforgevideo" version="1.0.1" targetFramework="net40" />

VocaluxeLib/Log/CBenchmark.cs

@@ -0,0 +1,165 @@
+using System;
+using System.Diagnostics;
+using VocaluxeLib.Utils;
+
+namespace VocaluxeLib.Log
+{
+    /// <summary>
+    /// Class for Benchmarks.
+    /// Can be used as instance or through the static wrappers.
+    /// </summary>
+    public class CBenchmark : IDisposable
+    {
+        // Pool of stop watches shared between all instances (we can get more than 5 but it only keeps 5)
+        private static readonly CObjectPool<Stopwatch> _WatchesPool = new CObjectPool<Stopwatch>(() => new Stopwatch(), 5);
+        private static readonly double _NanosecPerTick = (1000.0 * 1000.0 * 1000.0) / Stopwatch.Frequency;
+
+        // The stop watch used by this instance
+        private Stopwatch _Watch = null;
+        // The operation name the will be written to the log on events for this instance
+        private readonly string _OperationName;
+
+        /// <summary>
+        /// Creates a new benchmark instance.
+        /// </summary>
+        /// <param name="operationName">The name of the operation (will be used for log messages).</param>
+        public CBenchmark(string operationName)
+        {
+            _OperationName = operationName;
+        }
+
+        /// <summary>
+        /// Starts this benchmark.
+        /// </summary>
+        public void Start()
+        {
+            if (_Watch != null)
+                throw new InvalidOperationException("Timer is already running.");
+            _Watch = _WatchesPool.GetObject();
+            _Watch.Restart();
+            CLog.Information("Started {StartedOperation}", CLog.Params(_OperationName));
+        }
+
+        /// <summary>
+        /// Stops this benchmark.
+        /// </summary>
+        /// <param name="success">If true a success message will be added to the log otherwise a message for failure.</param>
+        public void Stop(bool success = true) 
+        {
+            if (_Watch == null)
+                throw new InvalidOperationException("Timer is not running.");
+            _Watch.Stop();
+            double duration = _GetElapsedTime(_Watch);
+
+            _WatchesPool.PutObject(_Watch);
+            _Watch = null;
+            if (success)
+                CLog.Information("Finished {StartedOperation} successfully in {Duration:#,##0.00}ms", CLog.Params(_OperationName, duration));
+            else
+                CLog.Information("Failed {StartedOperation} in {Duration:#,##0.00}ms", CLog.Params(_OperationName, duration));
+        }
+
+        /// <summary>
+        /// Helper method to extract the elapsed time from a stopwatch.
+        /// </summary>
+        /// <param name="watch">The stopwatch.</param>
+        /// <returns>The elapsed time of the given stop watch.</returns>
+        private double _GetElapsedTime(Stopwatch watch)
+        {
+            if (Stopwatch.IsHighResolution && _NanosecPerTick > 0)
+                return (float)((_NanosecPerTick * watch.ElapsedTicks) / (1000.0 * 1000.0));
+            else
+                return watch.ElapsedMilliseconds;
+        }
+
+        /// <summary>
+        /// Ends a possibly running benchmark (sucessfully).
+        /// </summary>
+        public void Dispose()
+        {
+            if (_Watch != null)
+                Stop();
+        }
+
+        #region Static functions
+
+        /// <summary>
+        /// Logs the time from now to disposal of the returned object.
+        /// </summary>
+        /// <param name="operationName">The name of the operation (will be used for log messages).</param>
+        /// <returns>Object which needs to be disposed to stop the benchmark.</returns>
+        /// <example>
+        /// <code> 
+        /// using(CBenchmark.Time("TestOperation")){
+        ///     //do someting
+        /// }
+        /// </code>
+        /// </example>
+        public static IDisposable Time(string operationName)
+        {
+            CBenchmark benchmark = new CBenchmark(operationName);
+            benchmark.Start();
+            return benchmark;
+        }
+
+        /// <summary>
+        /// Logs the time from now to the call of End() on the returned object (== success) or it's disposal (== failure).
+        /// </summary>
+        /// <param name="operationName">The name of the operation (will be used for log messages).</param>
+        /// <returns>Object to stop the benchmark.</returns>
+        /// <example>
+        /// <code> 
+        /// using(var op = CBenchmark.Begin("TestOperation")){
+        ///     //do someting that could fail
+        ///     op.End();
+        /// }
+        /// </code>
+        /// </example>
+        public static COperation Begin(string operationName)
+        {
+            CBenchmark benchmark = new CBenchmark(operationName);
+            benchmark.Start();
+            return new COperation(benchmark);
+        }
+
+        #region Helper class for operation
+
+        /// <summary>
+        /// Helper object to end a benchmark (End() for success and Dispose() for failure).
+        /// </summary>
+        public class COperation : IDisposable
+        {
+            private readonly CBenchmark _Benchmark;
+
+            /// <summary>
+            /// Creates a new instance of the benchmark helper object.
+            /// </summary>
+            /// <param name="benchmark">The associated benchmark object.</param>
+            internal COperation(CBenchmark benchmark)
+            {
+                _Benchmark = benchmark;
+
+            }
+
+            /// <summary>
+            /// End the associated benchmark sucessfully.
+            /// </summary>
+            public void End()
+            {
+                _Benchmark.Stop(true);
+            }
+
+            /// <summary>
+            /// End the associated benchmark not sucessfully.
+            /// </summary>
+            public void Dispose()
+            {
+                _Benchmark.Stop(false);
+            }
+        }
+
+        #endregion
+
+        #endregion
+    }
+}

VocaluxeLib/Utils/ObjectPool.cs

@@ -0,0 +1,61 @@
+using System;
+using System.Collections.Concurrent;
+using System.Collections.Generic;
+using System.Linq;
+using System.Text;
+using System.Threading.Tasks;
+
+namespace VocaluxeLib.Utils
+{
+    // Modified version of https://docs.microsoft.com/en-us/dotnet/standard/collections/thread-safe/how-to-create-an-object-pool
+
+    /// <summary>
+    /// Pool for objects.
+    /// </summary>
+    /// <typeparam name="T">Type of the objects in the pool.</typeparam>
+    public class CObjectPool<T>
+    {
+        private readonly ConcurrentBag<T> _Objects;
+        private readonly Func<T> _ObjectGenerator;
+        private readonly int _Poolsize;
+
+        /// <summary>
+        /// Create a new object pool.
+        /// </summary>
+        /// <param name="objectGenerator">Function witch generate a new object instance.</param>
+        /// <param name="poolSize">Number of objects to keep in the pool.</param>
+        public CObjectPool(Func<T> objectGenerator, int poolSize)
+        {
+            if (objectGenerator == null)
+                throw new ArgumentNullException(nameof(objectGenerator));
+            if (poolSize <= 0)
+                throw new ArgumentNullException(nameof(poolSize));
+            _Objects = new ConcurrentBag<T>();
+            _ObjectGenerator = objectGenerator;
+            _Poolsize = poolSize;
+        }
+
+        /// <summary>
+        /// Get an object (from the pool or a new one).
+        /// </summary>
+        /// <returns>An object instance.</returns>
+        public T GetObject()
+        {
+            T item;
+            if (_Objects.TryTake(out item)) return item;
+            return _ObjectGenerator();
+        }
+
+        /// <summary>
+        /// Put an intance back to the pool.
+        /// </summary>
+        /// <param name="item">The object instance that is given back to the pool.</param>
+        public void PutObject(T item)
+        {
+            if(_Objects.Count < _Poolsize)
+                _Objects.Add(item);
+            else
+                (item as IDisposable)?.Dispose();
+        }
+    }
+}

VocaluxeLib/VocaluxeLib.csproj

@@ -103,10 +103,6 @@
       <HintPath>..\packages\Serilog.Sinks.TextWriter.2.1.0\lib\net45\Serilog.Sinks.TextWriter.dll</HintPath>
       <Private>True</Private>
     </Reference>
-    <Reference Include="SerilogTimings, Version=2.2.0.0, Culture=neutral, PublicKeyToken=ea6fc7d88906f03a, processorArchitecture=MSIL">
-      <HintPath>..\packages\SerilogTimings.2.2.0\lib\net45\SerilogTimings.dll</HintPath>
-      <Private>True</Private>
-    </Reference>
     <Reference Include="System" />
     <Reference Include="System.Drawing" />
     <Reference Include="System.Windows.Forms" />
@@ -129,6 +125,7 @@
       <DesignTime>True</DesignTime>
       <DependentUpon>CLogFunctions.tt</DependentUpon>
     </Compile>
+    <Compile Include="Log\CBenchmark.cs" />
     <Compile Include="Menu\CBackground.cs" />
     <Compile Include="CBasic.cs" />
     <Compile Include="Menu\CButton.cs" />
@@ -157,6 +154,7 @@
     <Compile Include="Menu\IThemeable.cs" />
     <Compile Include="Menu\SingNotes\CNoteBars.cs" />
     <Compile Include="Utils\Combinatorics\CCombinations.cs" />
+    <Compile Include="Utils\ObjectPool.cs" />
     <Compile Include="XmlStructs.cs" />
     <Compile Include="Xml\CTypeExtensions.cs" />
     <Compile Include="Xml\CXmlDeserializer.cs" />

VocaluxeLib/packages.config

@@ -5,5 +5,4 @@
   <package id="Serilog.Sinks.Console" version="3.1.1" targetFramework="net471" />
   <package id="Serilog.Sinks.File" version="4.0.0" targetFramework="net471" />
   <package id="Serilog.Sinks.TextWriter" version="2.1.0" targetFramework="net471" />
-  <package id="SerilogTimings" version="2.2.0" targetFramework="net471" />
 </packages>