From 1e90938f995640248b5a6253e2a54bc946c866cf Mon Sep 17 00:00:00 2001 From: Maoni0 Date: Fri, 30 Jul 2021 18:56:56 -0700 Subject: [PATCH] Some improvements to RF + added a maximumWaitTime config default to 10 mins + actually breaks into the debugger when it times out when debugBreakOnTestHang is specified + prints out the progress while we wait so it's obvious if it's hung or just because some tests are taking a long time. example output - [7/30/2021 6:52:26 PM 1] ============current number of tests running 14, allocated 50,040,808,336 so far, 879,122,336 since last; (GC 439:420:420), waited 55s [7/30/2021 6:52:26 PM 1] Still running: DirectedGraph.dll [7/30/2021 6:52:26 PM 1] Still running: LargeObjectAlloc.dll [7/30/2021 6:52:26 PM 1] Still running: LargeObjectAlloc1.dll [7/30/2021 6:52:29 PM 1] Still running: LargeObjectAlloc2.dll --- .../Framework/ReliabilityConfiguration.cs | 3 + .../Stress/Framework/ReliabilityFramework.cs | 64 +++++++++++++------ .../GC/Stress/Framework/ReliabilityTestSet.cs | 16 +++++ 3 files changed, 62 insertions(+), 21 deletions(-) diff --git a/src/tests/GC/Stress/Framework/ReliabilityConfiguration.cs b/src/tests/GC/Stress/Framework/ReliabilityConfiguration.cs index cf2b5723585cda..d49105392fe711 100644 --- a/src/tests/GC/Stress/Framework/ReliabilityConfiguration.cs +++ b/src/tests/GC/Stress/Framework/ReliabilityConfiguration.cs @@ -404,6 +404,9 @@ private void GetTestsToRun(string testConfig) _curTestSet.MaximumTime = ConvertTimeValueToTestRunTime(timeValue); } + break; + case "maximumWaitTime": + _curTestSet.MaximumWaitTime = ConvertTimeValueToTestRunTime(currentXML.Value); break; case "id": _curTestSet.FriendlyName = currentXML.Value; diff --git a/src/tests/GC/Stress/Framework/ReliabilityFramework.cs b/src/tests/GC/Stress/Framework/ReliabilityFramework.cs index e56d5e33898f5d..edad71e91b00a4 100644 --- a/src/tests/GC/Stress/Framework/ReliabilityFramework.cs +++ b/src/tests/GC/Stress/Framework/ReliabilityFramework.cs @@ -630,7 +630,6 @@ public int RunReliabilityTests(string testConfig, bool doReplay) return (99); } -#if !PROJECTK_BUILD [DllImport("kernel32.dll")] private extern static void DebugBreak(); @@ -639,7 +638,6 @@ public int RunReliabilityTests(string testConfig, bool doReplay) [DllImport("kernel32.dll")] private extern static void OutputDebugString(string debugStr); -#endif /// /// Checks to see if we should block all execution due to a fatal error @@ -661,20 +659,11 @@ private static void NoExitPoll() } internal static void MyDebugBreak(string extraData) { -#if !PROJECTK_BUILD if (IsDebuggerPresent()) { - OutputDebugString(String.Format("\r\n\r\n\r\nRELIABILITYFRAMEWORK DEBUGBREAK: Breaking in because test throw an exception ({0})\r\n\r\n\r\n", extraData)); + Console.WriteLine(string.Format("DebugBreak: {0}", extraData)); DebugBreak(); } - else -#else - if (Debugger.IsAttached) - { - Console.WriteLine(string.Format("DebugBreak: breaking in because test threw an exception: {0}", extraData)); - Debugger.Break(); - } -#endif { // We need to stop the process now, // but all the threads are still running @@ -1081,11 +1070,33 @@ private void TestSetShutdown(int totalTestsToRun) _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, msg); Console.WriteLine(msg); + int secondsIter = 5; int waitCnt = 0; - while (_testsRunningCount > 0 && waitCnt < 7200) // wait a max of 2 hours for the tests to exit... - { - Thread.Sleep(1000); - Console.Write("\b\b\b\b{0,4}", _testsRunningCount); + int waitCntTotal = _curTestSet.MaximumWaitTime * 60 / secondsIter; + msg = String.Format("START WAITING for {0}s", _curTestSet.MaximumWaitTime * 60); + _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, msg); + long lastAllocatedBytes = GC.GetTotalAllocatedBytes(false); + while (_testsRunningCount > 0 && waitCnt < waitCntTotal) + { + Thread.Sleep(secondsIter * 1000); + long currentAllocatedBytes = GC.GetTotalAllocatedBytes(false); + msg = String.Format("============current number of tests running {0,4}, allocated {1:n0} so far, {2:n0} since last; (GC {3}:{4}:{5}), waited {6}s", + _testsRunningCount, currentAllocatedBytes, (currentAllocatedBytes - lastAllocatedBytes), + GC.CollectionCount(0), + GC.CollectionCount(1), + GC.CollectionCount(2), + (waitCnt * secondsIter)); + lastAllocatedBytes = currentAllocatedBytes; + _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, msg); + + for (int i = 0; i < _curTestSet.Tests.Length; i++) + { + if (_curTestSet.Tests[i].RunningCount != 0) + { + msg = String.Format("Still running: {0}", _curTestSet.Tests[i].RefOrID); + _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, msg); + } + } waitCnt++; } } @@ -1093,13 +1104,12 @@ private void TestSetShutdown(int totalTestsToRun) // let the user know what tests haven't finished... if (_testsRunningCount != 0) { - string msg; - + _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, "************Timeout reached************"); for (int i = 0; i < _curTestSet.Tests.Length; i++) { if (_curTestSet.Tests[i].RunningCount != 0) { - msg = String.Format("Still running: {0}", _curTestSet.Tests[i].RefOrID); + string msg = String.Format("Still running: {0}", _curTestSet.Tests[i].RefOrID); _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, msg); Console.WriteLine(msg); AddFailure("Test Hang", _curTestSet.Tests[i], -1); @@ -1116,6 +1126,9 @@ private void TestSetShutdown(int totalTestsToRun) [MethodImpl(MethodImplOptions.NoInlining)] private void TestIsHungDebugBreak() { + string msg = String.Format("break"); + _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, msg); + MyDebugBreak("TestHang"); } @@ -1165,7 +1178,8 @@ private void StartTest(ReliabilityTest test) Interlocked.Increment(ref _testsRunningCount); test.TestStarted(); - _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.TestStarter, String.Format("RF.StartTest, RTs({0}) - Instances of this test: {1} - New Test:{2}", _testsRunningCount, test.RunningCount, test.RefOrID)); + _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.TestStarter, String.Format("RF.StartTest, RTs({0}) - Instances of this test: {1} - New Test:{2}, {3} threads", + _testsRunningCount, test.RunningCount, test.RefOrID, Process.GetCurrentProcess().Threads.Count)); newThread.Start(test); } @@ -1207,7 +1221,11 @@ private void StartTestWorker(object test) #if PROJECTK_BUILD Task.Factory.StartNew(() => { - Console.WriteLine("==============================running test: {0}==============================", daTest.Assembly); + string msg = String.Format("==============================[tid: {0, 4}, running test: {1} STATUS: START, {2} tests running {3} threads ==============================", + Thread.CurrentThread.ManagedThreadId, daTest.Assembly, _testsRunningCount, + Process.GetCurrentProcess().Threads.Count); + _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, msg); + try { daTest.EntryPointMethod.Invoke(null, new object[] { (daTest.Arguments == null) ? new string[0] : daTest.GetSplitArguments() }); @@ -1220,6 +1238,10 @@ private void StartTestWorker(object test) Console.WriteLine(e); } + msg = String.Format("==============================[tid: {0, 4}, running test: {1} STATUS: DONE, {2} tests running {3} threads ==============================", + Thread.CurrentThread.ManagedThreadId, daTest.Assembly, _testsRunningCount, + Process.GetCurrentProcess().Threads.Count); + _logger.WriteToInstrumentationLog(_curTestSet, LoggingLevels.StartupShutdown, msg); Interlocked.Increment(ref _testsRanCount); SignalTestFinished(daTest); }); diff --git a/src/tests/GC/Stress/Framework/ReliabilityTestSet.cs b/src/tests/GC/Stress/Framework/ReliabilityTestSet.cs index 04450fe316b355..7116d01215f46a 100644 --- a/src/tests/GC/Stress/Framework/ReliabilityTestSet.cs +++ b/src/tests/GC/Stress/Framework/ReliabilityTestSet.cs @@ -14,6 +14,7 @@ public class ReliabilityTestSet { private int _maximumTestLoops = 0; // default run based on time. private int _maximumExecutionTime = 60; // 60 minute run by default. + private int _maximumWaitTime = 10; // 10 minute wait by default. private int _percentPassIsPass = System.Environment.GetEnvironmentVariable("PERCENTPASSISPASS") == null ? -1 : Convert.ToInt32(System.Environment.GetEnvironmentVariable("PERCENTPASSISPASS")); private int[] _minPercentCPUStaggered_times = null; private int[] _minPercentCPUStaggered_usage = null; @@ -94,6 +95,21 @@ public int MaximumTime } } + /// + /// Maximum wait time, in minutes. + /// + public int MaximumWaitTime + { + get + { + return (_maximumWaitTime); + } + set + { + _maximumWaitTime = value; + } + } + public string FriendlyName { get