diff --git a/Vocaluxe/Base/CGraphics.cs b/Vocaluxe/Base/CGraphics.cs index 495090a8..8f8e22fd 100644 --- a/Vocaluxe/Base/CGraphics.cs +++ b/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)); diff --git a/Vocaluxe/Base/CSongs.cs b/Vocaluxe/Base/CSongs.cs index e2a6e3f8..5c9b1943 100644 --- a/Vocaluxe/Base/CSongs.cs +++ b/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(); 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); diff --git a/Vocaluxe/Base/Fonts/CFonts.cs b/Vocaluxe/Base/Fonts/CFonts.cs index a91faec2..fbb7d236 100644 --- a/Vocaluxe/Base/Fonts/CFonts.cs +++ b/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(); } diff --git a/Vocaluxe/Program.cs b/Vocaluxe/Program.cs index 84ea160b..eb8b5a11 100644 --- a/Vocaluxe/Program.cs +++ b/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"); diff --git a/Vocaluxe/Screens/CScreenLoad.cs b/Vocaluxe/Screens/CScreenLoad.cs index 7ace4847..38f28903 100644 --- a/Vocaluxe/Screens/CScreenLoad.cs +++ b/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(); } diff --git a/Vocaluxe/Vocaluxe.csproj b/Vocaluxe/Vocaluxe.csproj index 8b69d5f0..9f4706c5 100644 --- a/Vocaluxe/Vocaluxe.csproj +++ b/Vocaluxe/Vocaluxe.csproj @@ -183,10 +183,6 @@ ..\packages\Serilog.Sinks.TextWriter.2.1.0\lib\net45\Serilog.Sinks.TextWriter.dll True - - ..\packages\SerilogTimings.2.2.0\lib\net45\SerilogTimings.dll - True - diff --git a/Vocaluxe/packages.config b/Vocaluxe/packages.config index 1cb54eb4..9b219db0 100644 --- a/Vocaluxe/packages.config +++ b/Vocaluxe/packages.config @@ -6,7 +6,6 @@ - diff --git a/VocaluxeLib/Log/CBenchmark.cs b/VocaluxeLib/Log/CBenchmark.cs new file mode 100644 index 00000000..60e5818b --- /dev/null +++ b/VocaluxeLib/Log/CBenchmark.cs @@ -0,0 +1,165 @@ +using System; +using System.Diagnostics; +using VocaluxeLib.Utils; + +namespace VocaluxeLib.Log +{ + /// + /// Class for Benchmarks. + /// Can be used as instance or through the static wrappers. + /// + 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 _WatchesPool = new CObjectPool(() => 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; + + /// + /// Creates a new benchmark instance. + /// + /// The name of the operation (will be used for log messages). + public CBenchmark(string operationName) + { + _OperationName = operationName; + } + + /// + /// Starts this benchmark. + /// + 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)); + } + + /// + /// Stops this benchmark. + /// + /// If true a success message will be added to the log otherwise a message for failure. + 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)); + } + + /// + /// Helper method to extract the elapsed time from a stopwatch. + /// + /// The stopwatch. + /// The elapsed time of the given stop watch. + private double _GetElapsedTime(Stopwatch watch) + { + if (Stopwatch.IsHighResolution && _NanosecPerTick > 0) + return (float)((_NanosecPerTick * watch.ElapsedTicks) / (1000.0 * 1000.0)); + else + return watch.ElapsedMilliseconds; + } + + /// + /// Ends a possibly running benchmark (sucessfully). + /// + public void Dispose() + { + if (_Watch != null) + Stop(); + } + + #region Static functions + + /// + /// Logs the time from now to disposal of the returned object. + /// + /// The name of the operation (will be used for log messages). + /// Object which needs to be disposed to stop the benchmark. + /// + /// + /// using(CBenchmark.Time("TestOperation")){ + /// //do someting + /// } + /// + /// + public static IDisposable Time(string operationName) + { + CBenchmark benchmark = new CBenchmark(operationName); + benchmark.Start(); + return benchmark; + } + + /// + /// Logs the time from now to the call of End() on the returned object (== success) or it's disposal (== failure). + /// + /// The name of the operation (will be used for log messages). + /// Object to stop the benchmark. + /// + /// + /// using(var op = CBenchmark.Begin("TestOperation")){ + /// //do someting that could fail + /// op.End(); + /// } + /// + /// + public static COperation Begin(string operationName) + { + CBenchmark benchmark = new CBenchmark(operationName); + benchmark.Start(); + return new COperation(benchmark); + } + + #region Helper class for operation + + /// + /// Helper object to end a benchmark (End() for success and Dispose() for failure). + /// + public class COperation : IDisposable + { + private readonly CBenchmark _Benchmark; + + /// + /// Creates a new instance of the benchmark helper object. + /// + /// The associated benchmark object. + internal COperation(CBenchmark benchmark) + { + _Benchmark = benchmark; + + } + + /// + /// End the associated benchmark sucessfully. + /// + public void End() + { + _Benchmark.Stop(true); + } + + /// + /// End the associated benchmark not sucessfully. + /// + public void Dispose() + { + _Benchmark.Stop(false); + } + } + + #endregion + + #endregion + } +} diff --git a/VocaluxeLib/Utils/ObjectPool.cs b/VocaluxeLib/Utils/ObjectPool.cs new file mode 100644 index 00000000..7f1b75fb --- /dev/null +++ b/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 + + /// + /// Pool for objects. + /// + /// Type of the objects in the pool. + public class CObjectPool + { + private readonly ConcurrentBag _Objects; + private readonly Func _ObjectGenerator; + private readonly int _Poolsize; + + /// + /// Create a new object pool. + /// + /// Function witch generate a new object instance. + /// Number of objects to keep in the pool. + public CObjectPool(Func objectGenerator, int poolSize) + { + if (objectGenerator == null) + throw new ArgumentNullException(nameof(objectGenerator)); + if (poolSize <= 0) + throw new ArgumentNullException(nameof(poolSize)); + _Objects = new ConcurrentBag(); + _ObjectGenerator = objectGenerator; + _Poolsize = poolSize; + } + + /// + /// Get an object (from the pool or a new one). + /// + /// An object instance. + public T GetObject() + { + T item; + if (_Objects.TryTake(out item)) return item; + return _ObjectGenerator(); + } + + /// + /// Put an intance back to the pool. + /// + /// The object instance that is given back to the pool. + public void PutObject(T item) + { + if(_Objects.Count < _Poolsize) + _Objects.Add(item); + else + (item as IDisposable)?.Dispose(); + } + } +} diff --git a/VocaluxeLib/VocaluxeLib.csproj b/VocaluxeLib/VocaluxeLib.csproj index c8d5068e..55d77e22 100644 --- a/VocaluxeLib/VocaluxeLib.csproj +++ b/VocaluxeLib/VocaluxeLib.csproj @@ -103,10 +103,6 @@ ..\packages\Serilog.Sinks.TextWriter.2.1.0\lib\net45\Serilog.Sinks.TextWriter.dll True - - ..\packages\SerilogTimings.2.2.0\lib\net45\SerilogTimings.dll - True - @@ -129,6 +125,7 @@ True CLogFunctions.tt + @@ -157,6 +154,7 @@ + diff --git a/VocaluxeLib/packages.config b/VocaluxeLib/packages.config index 66ace7ae..7bd9eaac 100644 --- a/VocaluxeLib/packages.config +++ b/VocaluxeLib/packages.config @@ -5,5 +5,4 @@ - \ No newline at end of file