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);
}
}