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 Basics() { UT_INIT(); Log.SetVerbosity(new ConsoleLogger(), Verbosity.Verbose, "/"); Log.MapThreadName("UnitTest"); Log.SetDomain("TickWatch", Scope.Method); Log.Info("\n### TicksBasics ###"); // check times { Ticks t = new Ticks(); t.FromNanos(42); // beyond resolution in C#: UT_EQ( t.InNanos(), 42L); UT_EQ(t.InMicros(), 0L); UT_EQ(t.InMillis(), 0L); UT_EQ(t.InSeconds(), 0L); t.FromMicros(42); UT_EQ(t.InNanos(), 42000L); UT_EQ(t.InMicros(), 42L); UT_EQ(t.InMillis(), 0L); UT_EQ(t.InSeconds(), 0L); t.FromMillis(42); UT_EQ(t.InNanos(), 42000000L); UT_EQ(t.InMicros(), 42000L); UT_EQ(t.InMillis(), 42L); UT_EQ(t.InSeconds(), 0L); t.FromSeconds(42); UT_EQ(t.InNanos(), 42000000000L); UT_EQ(t.InMicros(), 42000000L); UT_EQ(t.InMillis(), 42000L); UT_EQ(t.InSeconds(), 42L); Ticks diff = new Ticks(); diff.FromMillis(100); t.Add(diff); UT_EQ(t.InNanos(), 42100000000L); UT_EQ(t.InMicros(), 42100000L); UT_EQ(t.InMillis(), 42100L); UT_EQ(t.InSeconds(), 42L); t.Sub(diff); UT_EQ(t.InNanos(), 42000000000L); UT_EQ(t.InMicros(), 42000000L); UT_EQ(t.InMillis(), 42000L); UT_EQ(t.InSeconds(), 42L); t.FromMillis(100); UT_EQ(t.InHertz(), 10.0); t.FromMillis(300); UT_EQ(t.InHertz(0), 3.0); UT_EQ(t.InHertz(1), 3.3); UT_EQ(t.InHertz(2), 3.33); UT_EQ(t.InHertz(5), 3.33333); } // check internal frequency { double freq = Ticks.InternalFrequency; Log.Info("TickWatch InternalFrequency: " + freq); UT_TRUE(freq >= 1000000.0); } // check TickWatch creation time { Ticks creationTimeDiff = new Ticks(); creationTimeDiff.Sub(Ticks.CreationTime); Log.Info("TickWatch library creation was: " + creationTimeDiff.InNanos() + "ns ago"); Log.Info("TickWatch library creation was: " + creationTimeDiff.InMicros() + "µs ago"); Log.Info("TickWatch library creation was: " + creationTimeDiff.InMillis() + "ms ago"); Log.Info("TickWatch library creation was: " + creationTimeDiff.InSeconds() + "s ago"); UT_TRUE(creationTimeDiff.InNanos() > 100); // It should really take 100 nanoseconds to get here! UT_TRUE(creationTimeDiff.InSeconds() < 3600); // these test will probably not last an hour } // check if we could sleep for 100ms { Ticks start = new Ticks(); ALIB.SleepMillis(30); Ticks sleepTime = new Ticks(); sleepTime.Sub(start); Log.Info("TickWatch diff after 100ms sleep: " + sleepTime.InMillis() + " ms"); UT_TRUE(sleepTime.InMillis() > 28); UT_TRUE(sleepTime.InMillis() < 150); // should work even on heavily loaded machines } }
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); } }