namespace Framework { using Framework.Server; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Primitives; using System; using System.Collections.Concurrent; using System.Collections.Generic; using System.Diagnostics; using System.Linq; using System.Text; using System.Threading; internal static class UtilStopwatch { /// /// (RequestId, (RequestPath), Collection). /// private static readonly ConcurrentDictionary RequestIdToStopwatchCollectionList = new ConcurrentDictionary(); /// /// Stopwatch collection for (RequestId, RequestPath). If more than one request of same path has to be processed, a second stopwatch Collection class is created. /// private class Collection { public Collection() { this.Id = Interlocked.Increment(ref id); // Thread safe counter } private static int id = 0; public int Id; /// /// Gets NavigatePath. This stopwatch Collection is used only for this NavigatePath (request) path. /// public string NavigatePath; /// /// Gets RequestCount. Number of requests this stopwatch Collection has been used for. /// public int RequestCount; /// /// (Name, Stopwatch). /// public readonly Dictionary List = new Dictionary(); /// /// Gets or sets IsReleased. If true, StopwatchCollection has been released and can be reaused. /// public bool IsReleased; /// /// Gets LogText. Used to add some logging information at the end of request. /// public StringBuilder LogText = new StringBuilder(); } private class Item { public Stopwatch Stopwatch; /// /// Gets IsStart. Ensure sequence start, stop, start, stop is always correct. /// public bool IsStart; /// /// Gets StartCount. Number of times this stopwatch has been started. It is resetted every 10 requests. /// Same stopwatch (name) can be started and stopped multiple times in one request. /// public int StartCount; } private static Collection CollectionCurrent { get { var result = RequestIdToStopwatchCollectionList.GetOrAdd(requestId.Value, (key) => { var released = RequestIdToStopwatchCollectionList.Where(item => item.Value.IsReleased == true && item.Value.NavigatePath == UtilServer.Context.Request.Path.Value).FirstOrDefault(); if (!released.Equals(default(KeyValuePair))) // released != null { released.Value.IsReleased = false; if (RequestIdToStopwatchCollectionList.TryRemove(released.Key, out Collection stopwatchCollection)) { UtilFramework.Assert(released.Value == stopwatchCollection); return stopwatchCollection; } } return new Collection { NavigatePath = UtilServer.Context?.Request.Path.Value }; // Also called by command cli deployDb }); return result; } } private static Dictionary StopwatchList { get { return CollectionCurrent.List; } } internal static void TimeStart(string name) { if (!StopwatchList.ContainsKey(name)) { StopwatchList[name] = new Item { Stopwatch = new Stopwatch() }; } UtilFramework.Assert(StopwatchList[name].IsStart == false); StopwatchList[name].Stopwatch.Start(); StopwatchList[name].IsStart = true; StopwatchList[name].StartCount += 1; } internal static void TimeStop(string name) { UtilFramework.Assert(StopwatchList[name].IsStart == true); StopwatchList[name].Stopwatch.Stop(); StopwatchList[name].IsStart = false; } /// /// Write logging information to the end of the request. /// internal static void Log(string text) { CollectionCurrent.LogText.AppendLine(text); } /// /// Log stopwatch to console. /// internal static void TimeLog() { int pathCount = RequestIdToStopwatchCollectionList.Where(item => item.Value.NavigatePath == UtilServer.Context.Request.Path.Value).Count(); var collection = CollectionCurrent; StringBuilder result = new StringBuilder(); result.AppendLine(string.Format("CollectionId={0}/{1}; Path={2}; RequestCount={3}; PathCount={4};", collection.Id, RequestIdToStopwatchCollectionList.Count, collection.NavigatePath, collection.RequestCount, pathCount)); foreach (var item in collection.List.OrderBy(item => item.Key)) // Order by stopwatch name. { // Calculate average time per max 10 requests. double second = ((double)item.Value.Stopwatch.ElapsedTicks / (double)Stopwatch.Frequency) / collection.RequestCount; result.AppendLine(string.Format("Time={0:000.0}ms; Name={1}; StartCount={2};", second * 1000, item.Key, item.Value.StartCount)); } result.AppendLine(collection.LogText.ToString()); UtilServer.Logger(typeof(UtilStopwatch).Name).LogInformation(result.ToString().TrimEnd(Environment.NewLine.ToCharArray())); } /// /// Gets requestId. Id of current request. /// private static readonly AsyncLocal requestId = new AsyncLocal(); /// /// Bind unused stopwatch to this request. /// internal static void RequestBind() { UtilFramework.Assert(requestId.Value == Guid.Empty); requestId.Value = Guid.NewGuid(); var collection = CollectionCurrent; collection.RequestCount += 1; collection.LogText.Clear(); // Average time is calculated based on max every 10 requests. if (CollectionCurrent.RequestCount > 10) { CollectionCurrent.RequestCount = 1; foreach (var item in CollectionCurrent.List) { item.Value.Stopwatch.Reset(); item.Value.StartCount = 0; } } } /// /// Release stopwatch used for this request. /// internal static void RequestRelease() { RequestIdToStopwatchCollectionList[requestId.Value].IsReleased = true; foreach (var item in RequestIdToStopwatchCollectionList[requestId.Value].List) { item.Value.IsStart = false; item.Value.Stopwatch.Stop(); } } } }