//****************************************************************************************************** // LoadingAdjustedTimestamp.cs - Gbtc // // Copyright © 2016, Grid Protection Alliance. All Rights Reserved. // // Licensed to the Grid Protection Alliance (GPA) under one or more contributor license agreements. See // the NOTICE file distributed with this work for additional information regarding copyright ownership. // The GPA licenses this file to you under the Eclipse Public License -v 1.0 (the "License"); you may // not use this file except in compliance with the License. You may obtain a copy of the License at: // // http://www.opensource.org/licenses/eclipse-1.0.php // // Unless agreed to in writing, the subject software distributed under the License is distributed on an // "AS-IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. Refer to the // License for the specific language governing permissions and limitations. // // Code Modification History: // ---------------------------------------------------------------------------------------------------- // 11/15/2016 - Steven E. Chisholm // Generated original version of source code. // // //****************************************************************************************************** using System; using System.Threading; using GSF.Diagnostics; namespace GSF.Threading { /// /// This will provide the user with a timestamp based upon system loading. This timestamp will only move forward in time and may advance /// rapidly when trying to catch up with system time. /// /// /// The purpose for this class is to allow LagTime values to dynamically adjust based on perceived system performance. /// There were issues where the system would have multi second delays introduced based on exception handling or long garbage collection /// cycles that would cause all measurements to arrive outside the typical system lag time. This class /// attempts to detect when these events occur and provide increased lag time during these windows. /// public static class LoadingAdjustedTimestamp { /// /// This event will be raised when the idle thread is falling behind, but the real-time thread is keeping up. /// This should only be used by certain diagnostics code to dump the current thread pool work items. /// internal static event Action OnHighLoad; private static readonly LogPublisher Log; private static readonly LogEventPublisher LogLoadingClock; private static readonly LogEventPublisher LogSmall; private static readonly LogEventPublisher LogMedium; private static readonly LogEventPublisher LogLarge; private static readonly Thread MonitorHighThread; private static readonly Thread MonitorNormalThread; private static readonly Thread MonitorLowThread; private static long s_currentTime; private static ShortTime s_currentTimeSetTime; private static int s_highProcessCount; private static int s_normalProcessCount; private static int s_lowProcessCount; static LoadingAdjustedTimestamp() { Reset(); Log = Logger.CreatePublisher(typeof(LoadingAdjustedTimestamp), MessageClass.Component); LogLoadingClock = Log.RegisterEvent(MessageLevel.Info, MessageFlags.SystemHealth, $"Loading Clock is behind", 0, MessageRate.EveryFewSeconds(1), 1); LogSmall = Log.RegisterEvent(MessageLevel.Info, MessageFlags.SystemHealth, $"Short High Load Condition Detected", 0, MessageRate.EveryFewSeconds(10), 5); LogMedium = Log.RegisterEvent(MessageLevel.Warning, MessageFlags.SystemHealth, $"Medium High Load Condition Detected", 0, MessageRate.EveryFewSeconds(10), 5); LogLarge = Log.RegisterEvent(MessageLevel.Error, MessageFlags.SystemHealth, $"Long High Load Condition Detected", 0, MessageRate.EveryFewSeconds(10), 5); LogLoadingClock.ShouldRaiseMessageSupressionNotifications = false; LogSmall.ShouldRaiseMessageSupressionNotifications = false; LogMedium.ShouldRaiseMessageSupressionNotifications = false; LogLarge.ShouldRaiseMessageSupressionNotifications = false; MonitorHighThread = new Thread(MonitorHighPriority, short.MaxValue); MonitorHighThread.Priority = ThreadPriority.Highest; MonitorHighThread.IsBackground = true; MonitorHighThread.Start(); MonitorNormalThread = new Thread(MonitorNormalPriority, short.MaxValue); MonitorNormalThread.Priority = ThreadPriority.Normal; MonitorNormalThread.IsBackground = true; MonitorNormalThread.Start(); MonitorLowThread = new Thread(MonitorLowPriority, short.MaxValue); MonitorLowThread.Priority = ThreadPriority.Lowest; MonitorLowThread.IsBackground = true; MonitorLowThread.Start(); } private static void Reset() { Interlocked.Exchange(ref s_currentTime, DateTime.UtcNow.Ticks); s_currentTimeSetTime = ShortTime.Now; Interlocked.Exchange(ref s_highProcessCount, 0); Interlocked.Exchange(ref s_normalProcessCount, 0); Interlocked.Exchange(ref s_lowProcessCount, 0); } private static void MonitorHighPriority() { //This one will primarily detect when the process is paused. //This occurs when garbage collection occurs. ShortTime lastTime = ShortTime.Now; while (true) { try { Thread.Sleep(10); ShortTime currentTime = ShortTime.Now; long sleepDelta = (long)lastTime.ElapsedTicks(currentTime); long additionalDelay = sleepDelta - 10 * TimeSpan.TicksPerMillisecond; double additionalDelayMS = additionalDelay / (double)TimeSpan.TicksPerMillisecond; if (additionalDelayMS > 1000) { LogLarge.Publish(additionalDelayMS.ToString() + " ms (High Priority)"); } else if (additionalDelayMS > 300) { LogMedium.Publish(additionalDelayMS.ToString() + " ms (High Priority)"); } else if (additionalDelayMS > 100) { LogSmall.Publish(additionalDelayMS.ToString() + " ms (High Priority)"); } Interlocked.Increment(ref s_highProcessCount); AdjustRealtime(); lastTime = currentTime; } catch (Exception ex) { Log.Publish(MessageLevel.Warning, MessageFlags.BugReport, "Unexpected Exception Caught", null, null, ex); Thread.Sleep(1000); } } } private static void MonitorNormalPriority() { ShortTime lastTime = ShortTime.Now; while (true) { try { Thread.Sleep(10); ShortTime currentTime = ShortTime.Now; long sleepDelta = (long)lastTime.ElapsedTicks(currentTime); long additionalDelay = sleepDelta - 100 * TimeSpan.TicksPerMillisecond; double additionalDelayMS = additionalDelay / (double)TimeSpan.TicksPerMillisecond; if (additionalDelayMS > 1000) { LogLarge.Publish(additionalDelayMS.ToString() + " ms (Normal Priority)"); } else if (additionalDelayMS > 500) { LogMedium.Publish(additionalDelayMS.ToString() + " ms (Normal Priority)"); } Interlocked.Increment(ref s_normalProcessCount); lastTime = currentTime; } catch (Exception ex) { Log.Publish(MessageLevel.Warning, MessageFlags.BugReport, "Unexpected Exception Caught", null, null, ex); Thread.Sleep(1000); } } } private static void MonitorLowPriority() { ShortTime lastTime = ShortTime.Now; while (true) { try { Thread.Sleep(10); ShortTime currentTime = ShortTime.Now; long sleepDelta = (long)lastTime.ElapsedTicks(currentTime); long additionalDelay = sleepDelta - 100 * TimeSpan.TicksPerMillisecond; double additionalDelayMS = additionalDelay / (double)TimeSpan.TicksPerMillisecond; if (additionalDelayMS > 1000) { LogLarge.Publish(additionalDelayMS.ToString() + " ms (Normal Priority)"); } else if (additionalDelayMS > 500) { LogMedium.Publish(additionalDelayMS.ToString() + " ms (Normal Priority)"); } Interlocked.Increment(ref s_lowProcessCount); lastTime = currentTime; } catch (Exception ex) { Log.Publish(MessageLevel.Warning, MessageFlags.BugReport, "Unexpected Exception Caught", null, null, ex); Thread.Sleep(1000); } } } private static void AdjustRealtime() { //This method is supposed to be called every 10 milliseconds on a high priority thread. //However don't update the time unless 100ms has elapsed. //Since DateTime can be programmatically changed, I'm using CPU Registers. long physicalTimeSinceLastSet = (long)s_currentTimeSetTime.ElapsedTicks(); if (physicalTimeSinceLastSet < 100 * TimeSpan.TicksPerMillisecond) return; long clockSinceLastSet = DateTime.UtcNow.Ticks - s_currentTime; if (Math.Abs(physicalTimeSinceLastSet - clockSinceLastSet) > TimeSpan.TicksPerSecond) { Log.Publish(MessageLevel.Warning, MessageFlags.SystemHealth, "System time has been adjusted by more than 1 second. Resetting Loading Figures.", $"Expected Clock Change: {physicalTimeSinceLastSet / TimeSpan.TicksPerMillisecond} ms, Clock change: {clockSinceLastSet / TimeSpan.TicksPerMillisecond}"); Reset(); return; } if (clockSinceLastSet < 0) { Log.Publish(MessageLevel.Info, MessageFlags.SystemHealth, "System Clock did not advance.", $"Expected Clock Change: {physicalTimeSinceLastSet / TimeSpan.TicksPerMillisecond} ms, Clock change: {clockSinceLastSet / TimeSpan.TicksPerMillisecond}"); } int highDelay = Interlocked.Exchange(ref s_highProcessCount, 0); int normalDelay = Interlocked.Exchange(ref s_normalProcessCount, 0); int lowDelay = Interlocked.Exchange(ref s_lowProcessCount, 0); if (highDelay >= 5 && lowDelay <= 1) { try { OnHighLoad?.Invoke(); } catch (Exception) { } } long maxAdjustment = 0; if (lowDelay >= 7) { maxAdjustment = 500 * TimeSpan.TicksPerMillisecond; } else if (lowDelay >= 5) { maxAdjustment = 400 * TimeSpan.TicksPerMillisecond; } else if (normalDelay >= 7) { maxAdjustment = 300 * TimeSpan.TicksPerMillisecond; } else if (normalDelay >= 5) { maxAdjustment = 200 * TimeSpan.TicksPerMillisecond; } else if (highDelay >= 4) { maxAdjustment = 100 * TimeSpan.TicksPerMillisecond; } else { maxAdjustment = 50 * TimeSpan.TicksPerMillisecond; } if (maxAdjustment < clockSinceLastSet) { LogLoadingClock.Publish($"Behind by {clockSinceLastSet / TimeSpan.TicksPerMillisecond}ms adjusting by {maxAdjustment / TimeSpan.TicksPerMillisecond}ms"); } long adjustment = Math.Min(clockSinceLastSet, maxAdjustment); if (adjustment >= 0) { Interlocked.Exchange(ref s_currentTime, s_currentTime + adjustment); } s_currentTimeSetTime = ShortTime.Now; } /// /// Gets the current loading Adjusted Time /// public static DateTime CurrentTime { get { if (Environment.Is64BitProcess) { return new DateTime(s_currentTime); } return new DateTime(Interlocked.Read(ref s_currentTime)); } } } }