static Ticks()
{
// This static constructor is called once at the beginning of the life-cycle of this library.
// We use it to create
// a) a reference counter in DateTime ticks initialized to now and
// b) a Stopwatch object that we are starting.
// Within the Now() function of this class, we are then converting the Stopwatch measurement
// and add it to the initial timer.
// So, why are we doing this instead of just using DateTime.Now in method Now()?
// The answer is: DateTime.Now is very inefficient, because it creates a heap object that is
// then disposed right away. This version of Now() is around 15 times faster on the compiling platform.
CreationTime= new Ticks( DateTime.Now.Ticks );
// for the conversion in "millis since the epoch" we need the reference DayTime ticks
dateTimeTicks19700101= (new DateTime( 1970, 1, 1, 0, 0, 0 )).Ticks;
creationTimeStopWatch= new Stopwatch();
creationTimeStopWatch.Start();
InternalFrequency= Stopwatch.Frequency;
// conversion factor StopWatch to DateTime is:
// 10 million nanoseconds (the DateTime ticks per second) / by frequency of stopwatch
convSWToDT= 10000000d / (double) InternalFrequency;
}
public void ThreadLock_SpeedTest()
{
UT_INIT();
Log.SetVerbosity( new ConsoleLogger(), Verbosity.Verbose, "/" );
Log.MapThreadName( "UnitTest" );
Log.SetDomain( "TestTLock", Scope.Method );
ThreadLock aLock= new ThreadLock();
int repeats= 100000;
int rrepeats= 5;
Ticks stopwatch= new Ticks();
for ( int r= 0; r < rrepeats; r ++)
{
Log.Info("Run " + rrepeats );
aLock.SetSafeness( Safeness.Unsafe );
stopwatch.Set();
for ( int i= 0; i < repeats; i++ )
{
aLock.Acquire();
aLock.Release();
}
long time= stopwatch.Age().InMillis();
Log.Info("Safe mode, " + repeats + " lock/unlock ops: " + time + " ms" );
aLock.SetSafeness( Safeness.Safe );
stopwatch.Set();
for ( int i= 0; i < repeats; i++ )
{
//aLock.acquire();
//aLock.release();
// in java, adding the following two loops, results in similar execution speed
for ( int tt= 0; tt < 70; tt++ )
i+= tt;
for ( int tt= 0; tt < 70; tt++ )
i-= tt;
}
time= stopwatch.Age().InMillis();
Log.Info("Unsafe mode, " + repeats + " lock/unlock ops: " + time + " ms" );
}
}
/** ****************************************************************************************
* Returns the average length of all samples since this instance was created or reset.
* If no measurement was performed, the result value will be set to 0 ticks.
*
* @param result An object to store the result in. If not provided (null), a result
* object is created.
*
* @return The average sample time within the given or created object.
******************************************************************************************/
public Ticks GetAverage( Ticks result )
{
if ( result == null )
result= new Ticks();
result.SetRaw( cntSamples== 0 ? 0L : (sum.Raw() / cntSamples) );
return result;
}
/** ****************************************************************************************
* Creates a Ticks instance representing the same point in time or time span as the instance provided.
* @param copy The instance to copy the ticks value from.
******************************************************************************************/
public Ticks( Ticks copy ) { ticks= copy.ticks; }
/** ****************************************************************************************
* Returns the average length of all samples since this instance was created or reset.
* If no measurement was performed, the result value will be set to 0 ticks.
*
* Note: Attention: The object returned is a temporary object, deemed to be reused by other
* interface methods of this instance. Therefore, it must be used only until subsequent
* method invocations on this instance are performed (hence, also not thread safe!)
* Use #GetAverage(Ticks result) to provide a dedicated external result instance.
*
*
* @return The average length of all samples taken since the last reset.
******************************************************************************************/
public Ticks GetAverage()
{
if (tempTicks == null )
tempTicks= new Ticks( 0L );
return new Ticks( cntSamples== 0 ? 0L : (sum.Raw() / cntSamples) );
}
public void SpeedTest()
{
UT_INIT();
Log.SetVerbosity( new ConsoleLogger(), Verbosity.Verbose, "/" );
Log.MapThreadName( "UnitTest" );
Log.SetDomain( "TickWatch", Scope.Method );
Log.Info( "\n### TicksSpeedTest ###" );
for (int runs= 0; runs < 5; runs ++ )
{
int aLotOf= 100;
Ticks t= new Ticks();
Ticks tkMeasure= new Ticks();
for (int i= 0; i < aLotOf; i++ )
t.Set();
long nanos= tkMeasure.Age().InNanos();
long averageNanos= nanos/ aLotOf ;
Log.Info( "Doing " + aLotOf + " Ticks.Set() calls took " + nanos + " ns. This is an average of " + averageNanos + " nanoseconds per call" );
UT_TRUE ( averageNanos < 20000 ); // this is much slower on Windows than on mono/linux.
}
}
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 );
}
}
/** ****************************************************************************************
* Returns the time span between the value represented by this instance and the given TickWatch.
* If the given TickWatch represents an earlier point in time, the result is positive.
*
* Note: Attention: The object returned is a temporary object, deemed to be reused by other
* interface methods of this instance. Therefore, it must be used only until subsequent
* method invocations on this instance are performed (hence, also not thread safe!)
* Use #Since(Ticks result, Ticks result) to provide a dedicated external result instance.
*
* @param olderTime The value to compare this instance with
*
* @return The calculated time span, stored in a temporary object, not thread safe object
******************************************************************************************/
public Ticks Since( Ticks olderTime )
{
if (tempTicks == null )
tempTicks= new Ticks( 0L );
return Since( olderTime, tempTicks );
}
/** ****************************************************************************************
* Returns the time span between the value represented by this instance and the given TickWatch.
* If the given TickWatch represents an earlier point in time, the result is positive.
*
* @param olderTime The value to compare this instance with
* @param result The Ticks object to store the result in. If null, this is created.
* @return The calculated time span, stored in the given or created object.
******************************************************************************************/
public Ticks Since( Ticks olderTime, Ticks result )
{
if ( result == null )
result= new Ticks( this );
else
result.Set( this );
result.Sub( olderTime );
return result;
}
// #############################################################################################
// Interface Age, Since
// #############################################################################################
/** ****************************************************************************************
* Returns the time span between value represented by this instance and the current system time.
* If the internal value represents a historic point in time, the result is positive.
*
* Note: Attention: The object returned is a temporary object, deemed to be reused by other
* interface methods of this instance. Therefore, it must be used only until subsequent
* method invocations on this instance are performed (hence, also not thread safe!)
* Use #Age(Ticks result) to provide a dedicated external result instance.
*
* @return The age of this instance, stored in a temporary object, not thread safe object.
******************************************************************************************/
public Ticks Age( )
{
if (tempTicks == null )
tempTicks= new Ticks( 0L );
return Age( tempTicks );
}
/** ****************************************************************************************
* Returns the time span between value represented by this instance and the current time.
* If the internal value represents a historic point in time, the result is positive.
*
* @param result The Ticks object to store the result in. If null, this is created.
*
* @return The age of this instance, stored in the given or created object.
******************************************************************************************/
public Ticks Age( Ticks result )
{
if ( result == null )
result= new Ticks();
else
result.Set();
result.Sub( this );
return result;
}
/** ****************************************************************************************
* Subtracts the point in time or time span represented by the given Ticks instance from this instance.
* @param other The Ticks object to subtract the ticks from.
******************************************************************************************/
public void Sub( Ticks other ) { this.ticks-= other.ticks; }
/** ****************************************************************************************
* Adds the point in time or time span represented by the given Ticks instance to this instance.
* @param other The Ticks object to add the ticks from.
******************************************************************************************/
public void Add( Ticks other ) { this.ticks+= other.ticks; }
/** ****************************************************************************************
* Sets the point in time or time span represented by this instance to the value represented by
* the given Ticks instance.
* @param other The Ticks object to retrieve the new ticks value from.
******************************************************************************************/
public void Set( Ticks other ) { this.ticks= other.ticks; }
// #############################################################################################
// Other static interface methods
// #############################################################################################
/** ****************************************************************************************
* Suspends the current thread by calling Thread.Sleep().
* Provided for compatibility with other platform versions of ALib.
* Variants of this method are #SleepMillis, #SleepMicros and #SleepNanos.
*
* @param ticks Sleep time in \b %Ticks.
******************************************************************************************/
public static void Sleep(Ticks ticks)
{
if ( ticks.Raw() > 0 )
Thread.Sleep( TimeSpan.FromTicks( ticks.Raw() ) );
}
/** ****************************************************************************************
* Determines if this objects' age is higher than a given time span.
*
* @param waitTime A \b %Ticks object representing a time span.
* @return \c true if the given \b %Ticks object representing a time span is smaller
* or equal than our age. \c false otherwise.
******************************************************************************************/
public bool HasElapsed( Ticks waitTime )
{
return Age().Raw() >= waitTime.Raw();
}
public static void PerformanceTestRL()
{
// create a lox for release logging
Lox lox= new Lox( "ReleaseLox" );
TextLogger relLogger= Lox.CreateConsoleLogger();
MemoryLogger ml = new MemoryLogger();
lox.SetVerbosity( relLogger, Verbosity.Verbose, "/CON" );
lox.SetVerbosity( ml , Verbosity.Verbose, "/MEM" );
lox.Info( "/CON", "Logging simple info lines into a memory logger" );
AString msgBuf= new AString( );
long fastest= long.MaxValue;
Ticks timer= new Ticks();
int qtyLines= 100;
int qtyLoops= 1000;
if( System.Diagnostics.Debugger.IsAttached )
qtyLines= qtyLoops= 10;
for ( int i= 0 ; i < qtyLoops ; i++ )
{
#if ALOX_DBG_LOG || ALOX_REL_LOG
ml.MemoryLog.Clear();
#endif
timer.Set();
for ( int ii= 0 ; ii < qtyLines ; ii++ )
{
lox.Info( "/MEM", "Test Line" );
if( i== 0 && ii == 0) Console.WriteLine( ml.MemoryLog.ToString() );
}
long t= timer.Age().Raw();
if ( fastest > t )
{
fastest= t;
lox.Info( "/CON", msgBuf.Clear()._( "Pass " )._( i, 3)._( " is new fastest: ")
._( (int) (new Ticks( fastest)).InMicros(), 0)
._( " micros per ")._(qtyLines)._(" logs.") );
}
}
double microsPerLog= ( (double) (new Ticks(fastest)).InMicros() ) / qtyLines;
int logsPerSecond= (int)( 1000000.0 / microsPerLog);
lox.Info( "/CON", msgBuf._()._( " " )._( ESC.MAGENTA )._( "Fastest Release Logging: " )
._( microsPerLog )._( " micros per log (resp " )
._( logsPerSecond )._( " logs per second) " ) );
lox.RemoveLogger( ml );
lox.RemoveLogger( relLogger );
}
/** ****************************************************************************************
* Sets the internal start time value.
* @param t The value.
******************************************************************************************/
public void SetStartTime( Ticks t ) { ticks.Set( t ); }
public void DateTimeConversion()
{
UT_INIT();
Log.SetVerbosity( new ConsoleLogger(), Verbosity.Verbose, "/" );
Log.MapThreadName( "UnitTest" );
Log.SetDomain( "TickWatch", Scope.Method );
Log.Info( "DateTime.MinValue(): " + ( DateTime.MinValue.ToString() ) );
Log.Info( "DateTime.MaxValue(): " + ( DateTime.MaxValue.ToString() ) );
Ticks ticksNow= new Ticks();
// roundtrip 1
long millisEpochNow= ticksNow.InEpochMillis();
ticksNow.SetFromEpochMillis( millisEpochNow );
long ticksNowFromEpoch= ticksNow.Raw();
UT_TRUE( Math.Abs( ticksNow.Raw() - ticksNowFromEpoch ) < 50000 );
// roundtrip 2
long millis5_1_70_3_51= 0
+ ( 4L * 24L * 60L * 60L * 1000L )
+ ( 3L * 60L * 60L * 1000L )
+ ( 51L * 60L * 1000L );
long millis5_1_71_3_51= millis5_1_70_3_51
+ ( 365L * 24L * 60L * 60L * 1000L );
Ticks ticks5_1_70_3_51= new Ticks(); ticks5_1_70_3_51.SetFromEpochMillis( millis5_1_70_3_51 );
Ticks ticks5_1_71_3_51= new Ticks(); ticks5_1_71_3_51.SetFromEpochMillis( millis5_1_71_3_51 );
UT_TRUE( ticks5_1_70_3_51.Raw() < ticks5_1_71_3_51.Raw() );
long millis5_1_70_3_51_back= ticks5_1_70_3_51.InEpochMillis();
long millis5_1_71_3_51_back= ticks5_1_71_3_51.InEpochMillis();
UT_TRUE( millis5_1_70_3_51_back == millis5_1_70_3_51 );
UT_TRUE( millis5_1_71_3_51_back == millis5_1_71_3_51 );
// add 1 day, 2h, 3min and 4sec days:
Ticks tomorrow= new Ticks( ticksNow );
Ticks span= new Ticks();
span.FromMillis( (long) (new TimeSpan( 1,2,3,4 )).TotalMilliseconds);
tomorrow.Add ( span );
Log.Info( "Today: is: " + ( DateTime.Now.ToString() ) );
Log.Info( "Today: is: " + ( ticksNow .InDotNetDateTime().ToString() ) );
Log.Info( "Today: is: " + ( (new Ticks(ticksNowFromEpoch)) .InDotNetDateTime().ToString() ) );
Log.Info( "+1d, 2h,3m,4s: " + ( tomorrow .InDotNetDateTime().ToString() ) );
Log.Info( "5.1.70 3:51:00: " + ( ticks5_1_70_3_51 .InDotNetDateTime().ToString() ) );
Log.Info( "5.1.71 3:51:00: " + ( ticks5_1_71_3_51 .InDotNetDateTime().ToString() ) );
}
// #############################################################################################
// Interface to Measurement
// #############################################################################################
/** ****************************************************************************************
* Returns the time span between the current system time and the internal reference value.
* In addition this value is added to the sum of sample times and the sample counter is
* increased by one. Lastly the internal reference value is set to now. Therefore, a
* subsequent call to this function would measure the time span from this call to this
* subsequent call (if the internal reference value was not set differently meanwhile).
* Other interface methods dealing with samples are #GetSampleCnt, #GetCumulated and
* #GetAverage.
*
* @return The time difference between the current system time and the internal reference value.
******************************************************************************************/
public Ticks Sample ()
{
if (tempTicks == null )
tempTicks= new Ticks( 0L );
cntSamples++;
long old= ticks.Raw();
ticks.Set();
long diff= ticks.Raw() - old;
tempTicks.SetRaw( diff );
sum.Add( diff );
return tempTicks;
}
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 SetStartTime( DateTime? startTime= null, String loggerName= null,
[CallerLineNumber] int cln= 0,[CallerFilePath] String csf="",[CallerMemberName] String cmn="" )
{
#if ALOX_DBG_LOG || ALOX_REL_LOG
try { Acquire();
// initialize scope information
scopeInfo.Set( cln,csf,cmn, owner );
// check if start time was set
Ticks time= new Ticks( 0L );
if ( startTime != null)
time.SetFromDotNetDateTime( startTime.Value );
else
time.Set();
// request logger only from main domain tree
Logger logger= domains.GetLogger( loggerName );
if ( logger == null )
{
logInternal( Verbosity.Error, "LGR", intMsg.Clear()
._( '\"' ) ._NC( loggerName )._NC( "\": not found. Start time not set." ) );
return;
}
// do
logger.TimeOfCreation.Set( time );
logger.TimeOfLastLog .Set( time );
// log info on this
logInternal( Verbosity.Info, "LGR", intMsg.Clear()
._('\"')._NC(logger)._NC("\": Start time set to ")
._NC(startTime.HasValue? startTime.Value.ToString() : "<now>")._('.') );
} finally { Release(); }
#endif
}
