public void MeasureIncreasingDoublingLoop() { UT_INIT(); Log.SetVerbosity(new ConsoleLogger(), Verbosity.Verbose, "/"); Log.MapThreadName("UnitTest"); Log.SetDomain("TickWatch", Scope.Method); Log.Info("This test shows quite nicely, how the just in time compiler steps in when we are looping heavily!"); String testString = "-------------------------------------------------------------------------------------------#"; AString testAString = new AString(testString); TickWatch ttString = new TickWatch(); TickWatch ttAString = new TickWatch(); for (int run = 4; run < 20; run++) { int qtyLoops = (run == 0) ? 0 : (1 << (run - 1)); // use String.IndexOf() ttString.Reset(); int nonOptimizableUsedResultValue = 0; for (int i = 0; i < qtyLoops; i++) { nonOptimizableUsedResultValue += testString.IndexOf('#'); } Ticks sSample = ttString.Sample(); // use AString.IndexOf() ttAString.Reset(); for (int i = 0; i < qtyLoops; i++) { nonOptimizableUsedResultValue += testAString.IndexOf('#'); } Ticks aSample = ttAString.Sample(); if (nonOptimizableUsedResultValue > -1) // this is always true, just for the sake that the compiler does not optimize the whole code! { Log.Info(Log.Buf()._("Search loops ").Field()._(qtyLoops.ToString()).Field(6) ._(": time needed: ").Field()._((int)sSample.InNanos()).Field(8) ._(" / ").Field()._((int)aSample.InNanos()).Field(8) ._(" Ratio String/AString: ")._(((double)sSample.Raw()) / ((double)aSample.Raw())) ); } } }
public void Ages() { UT_INIT(); Log.SetVerbosity(new ConsoleLogger(), Verbosity.Verbose, "/"); Log.MapThreadName("UnitTest"); Log.SetDomain("TickWatch", Scope.Method); TickWatch tt = new TickWatch(); // minimum time measuring { tt.Start(); tt.Sample(); tt.Reset(); // we need to do this once before, otherwise C# might be // very slow. Obviously the optimizer... tt.Start(); tt.Sample(); long ttAverageInNanos = tt.GetAverage().InNanos(); long ttAverageInMicros = tt.GetAverage().InMicros(); long ttAverageInMillis = tt.GetAverage().InMillis(); Log.Info("TickWatch minimum measurement nanos: " + ttAverageInNanos); Log.Info("TickWatch minimum measurement micros: " + ttAverageInMicros); Log.Info("TickWatch minimum measurement millis: " + ttAverageInMillis); UT_TRUE(ttAverageInNanos < 5000); UT_TRUE(ttAverageInMicros <= 5); UT_TRUE(ttAverageInMillis == 0); } // minimum sleep time measuring { tt.Reset(); for (int i = 0; i < 100; i++) { ALIB.SleepNanos(1); tt.Sample(); } Ticks avg = tt.GetAverage(); Log.Info("100 probes of 1 ns of sleep leads to average sleep time of " + avg.InNanos() + " ns"); } // sleep two times 20 ms and probe it to an average { tt.Reset(); tt.Start(); ALIB.SleepMillis(20); tt.Sample(); ALIB.SleepMillis(80); tt.Start(); ALIB.SleepMillis(20); tt.Sample(); long cnt = tt.GetSampleCnt(); long avg = tt.GetAverage().InMillis(); double hertz = tt.GetAverage().InHertz(1); Log.Info("TickWatch sum is " + tt.GetCumulated().InMillis() + " after " + cnt + " times 20 ms sleep"); Log.Info(" average is: " + avg + " ms"); Log.Info(" in Hertz: " + hertz); UT_TRUE(hertz < 53); UT_TRUE(hertz > 30); // should work even on heavily loaded machines UT_EQ(2, cnt); UT_TRUE(avg >= 18); UT_TRUE(avg < 45); // should work even on heavily loaded machines } // Ticks Since { Ticks tt1 = new Ticks(); tt1.FromSeconds(1000); Ticks tt2 = new Ticks(); tt2.FromSeconds(1001); UT_TRUE(tt2.Since(tt1).InMillis() == 1000L); UT_TRUE(tt2.Since(tt1).InMicros() == 1000L * 1000L); UT_TRUE(tt2.Since(tt1).InNanos() == 1000L * 1000L * 1000L); } }