Ukg.Test.TimeMeasureTestLogger 1.0.0

TimeMeasureTestLogger

Allows to measure each step in test execution.

Installation

dotnet add package Ukg.Test.TimeMeasureTestLogger

How to use

Simple use

Create static constructor in test class, then add and configure loggers you need

static TimeMeasureTestLoggerExampleTest()
{
    TimeMeasureTestLogger.Singleton.AddLogger(new TimeMeasureConsoleLogger());
    TimeMeasureTestLogger.Singleton.AddLogger(new TimeMeasureFileLogger(<filepath>));
}

TimeMeasureConsoleLogger writes logs to standard output
TimeMeasureFileLogger writes logs to specific file

If you need some custom logger you can create your own logger implementing ITimeMeasureLogger interface

In the code snippet above you need to provide path to log file

TimeMeasureTestLogger.Singleton.AddLogger(new TimeMeasureFileLogger(filepath));

Inside your test add log messages you need

[TestMethod]
public void MyTest1()
{
    ...
    TimeMeasureTestLogger.Singleton.Log("Add log message here");
    ...
    TimeMeasureTestLogger.Singleton.Log("Add another log message here");
    ...
    TimeMeasureTestLogger.Singleton.Log("and so on as many as you need");
    ...
}

After test run log file will look like this

2024-07-17 15:48:15.411 [00.0][00.0]: Add log message here
2024-07-17 15:48:16.626 [01.2][01.2]: Add another log message here
2024-07-17 15:48:19.233 [03.8][02.6]: and so on as many as you need

Below is explanation what do numbers mean next to log messages

2024-07-17 15:48:15.411 [00.0][00.0]: Add log message here
2024-07-17 15:48:16.626 [01.2][01.2]: Add another log message here
2024-07-17 15:48:19.233 [03.8][02.6]: and so on as many as you need
                         ^^^^  ^^^^^ - this is a time elapsed since previous log message
                         ^^^^ -------- this is total elapsed time since test session started 

• If elapsed time is less than one minute then time will have only number of seconds and milliseconds: [02.6] which means 2 seconds and 600 milliseconds
• If elapsed time is more than one minute but less than one hour then time will include number of minutes as well: [03:02.6] which means 3 minutes 2 seconds and 600 milliseconds
• If elapsed time is more than one hour then time will include number of hours as well: [01:03:02.6] which means 1 hour 3 minutes 2 seconds and 600 milliseconds

Advanced use

Now we will create more advanced test using test initialization, cleanup, levels and sub methods

Levels

What are levels?

Level is an abstraction which allows to add additional timer each time level raised and remove additional timer each time level reduced. One of example for level is a sub method call from your test. In some cases you might want to add additional timer for you sub method and see how much time each step takes relatively to sub method start time.

You can raise levels as many times as you need.
Good example is when sub method calls another sub method. In this case we can raise level one more time for second sub method.

Repeat all steps from simple use example.

Add methods for test initialization and cleanup and advanced test as well.

[TestInitialize]
public void TestInitialize()
{
}

[TestCleanup]
public void TestCleanup()
{
}

[TestMethod]
public void MyTest2()
{
}

void SubMethod()
{
}

To raise level call TimeMeasureTestLogger.Singleton.LevelUp(<level_name>); method providing level name. Level name will help you identify messages related to this level.

To reduce level call TimeMeasureTestLogger.Singleton.LevelDown();

Lets add level to our methods.

[TestInitialize]
public void TestInitialize()
{
    TimeMeasureTestLogger.Singleton.LevelUp("TestInitialize()");
    TimeMeasureTestLogger.Singleton.LevelDown();
}

[TestCleanup]
public void TestCleanup()
{
    TimeMeasureTestLogger.Singleton.LevelUp("TestCleanup()");
    TimeMeasureTestLogger.Singleton.LevelDown();
}

[TestMethod]
public void MyTest2()
{
    TimeMeasureTestLogger.Singleton.LevelUp("MyTest2()");
    TimeMeasureTestLogger.Singleton.LevelDown();
}

void SubMethod()
{
    TimeMeasureTestLogger.Singleton.LevelUp("SubMethod()");
    TimeMeasureTestLogger.Singleton.LevelDown();
}

Tests may fail. Test initialization as well as test cleanup may fail too.
Lets wrap levels into try/finally blocks to properly manage levels.

[TestInitialize]
public void TestInitialize()
{
    try
    {
        TimeMeasureTestLogger.Singleton.LevelUp("TestInitialize()");
    }
    finally
    {
        TimeMeasureTestLogger.Singleton.LevelDown();
    }
}

[TestCleanup]
public void TestCleanup()
{
    try
    {
        TimeMeasureTestLogger.Singleton.LevelUp("TestCleanup()");
    }
    finally
    {
        TimeMeasureTestLogger.Singleton.LevelDown();
    }
}

[TestMethod]
public void MyTest2()
{
    try
    {
        TimeMeasureTestLogger.Singleton.LevelUp("MyTest2()");
    }
    finally
    {
        TimeMeasureTestLogger.Singleton.LevelDown();
    }
}

void SubMethod()
{
    try
    {
        TimeMeasureTestLogger.Singleton.LevelUp("SubMethod()");
    }
    finally
    {
        TimeMeasureTestLogger.Singleton.LevelDown();
    }
}

Writing log messages to loggers might lag. So TimeMeasureTestLogger doesn't write logs instantly but periodically in the background. This is good because it doesn't affect test execution time.

To make sure all logs saved and nothing is lost we need to flash logs at the end of each test. This can be archived calling TimeMeasureTestLogger.Singleton.Flush(); in the test cleanup method.

<pre> [TestCleanup] public void TestCleanup() { try { TimeMeasureTestLogger.Singleton.LevelUp("TestCleanup()"); } finally { TimeMeasureTestLogger.Singleton.LevelDown(); <b>TimeMeasureTestLogger.Singleton.Flush();</b> } } </pre>

Lets call submethod from our test

<pre> [TestMethod] public void MyTest2() { try { TimeMeasureTestLogger.Singleton.LevelUp("MyTest2()"); RandomSleep(); <b> for (int i = 0; i < 2; i++) { SubMethod(); } </b> } finally { TimeMeasureTestLogger.Singleton.LevelDown(); } } </pre>

Log file will look like this

2024-07-17 16:50:47.670 [00.0] - TestInitialize() [00.0] - [00.0]: - Start -
2024-07-17 16:50:47.803 [00.1] - TestInitialize() [00.1] - [00.1]: TestInitialize Step 1
2024-07-17 16:50:48.586 [00.9] - TestInitialize() [00.9] - [00.7]: TestInitialize Step 2
2024-07-17 16:50:49.420 [01.7] - TestInitialize() [01.7] - [00.8]: TestInitialize Step 3
2024-07-17 16:50:49.618 [01.9] - TestInitialize() [01.9] - [00.1]: TestInitialize Step 4
2024-07-17 16:50:50.332 [02.6] - TestInitialize() [02.6] - [00.7]: TestInitialize Step 5
2024-07-17 16:50:50.545 [02.8] - TestInitialize() [02.8] - [00.2]: - End -
2024-07-17 16:50:50.546 [02.8] - MyTest2() [00.0] - [00.0]: - Start -
2024-07-17 16:50:51.228 [03.5] - MyTest2() [00.6] - SubMethod() [00.0] - [00.6]: - Start -
2024-07-17 16:50:51.988 [04.3] - MyTest2() [01.4] - SubMethod() [00.7] - [00.7]: SubMethod Step 1
2024-07-17 16:50:52.321 [04.6] - MyTest2() [01.7] - SubMethod() [01.0] - [00.3]: SubMethod Step 2
2024-07-17 16:50:52.764 [05.0] - MyTest2() [02.2] - SubMethod() [01.5] - [00.4]: SubMethod Step 3
2024-07-17 16:50:53.755 [06.0] - MyTest2() [03.2] - SubMethod() [02.5] - [00.9]: SubMethod Step 4
2024-07-17 16:50:54.487 [06.8] - MyTest2() [03.9] - SubMethod() [03.2] - [00.7]: SubMethod Step 5
2024-07-17 16:50:55.154 [07.4] - MyTest2() [04.6] - SubMethod() [03.9] - [00.6]: - End -
2024-07-17 16:50:55.154 [07.4] - MyTest2() [04.6] - SubMethod() [00.0] - [00.0]: - Start -
2024-07-17 16:50:55.683 [08.0] - MyTest2() [05.1] - SubMethod() [00.5] - [00.5]: SubMethod Step 1
2024-07-17 16:50:56.473 [08.8] - MyTest2() [05.9] - SubMethod() [01.3] - [00.7]: SubMethod Step 2
2024-07-17 16:50:56.639 [08.9] - MyTest2() [06.0] - SubMethod() [01.4] - [00.1]: SubMethod Step 3
2024-07-17 16:50:56.789 [09.1] - MyTest2() [06.2] - SubMethod() [01.6] - [00.1]: SubMethod Step 4
2024-07-17 16:50:57.381 [09.7] - MyTest2() [06.8] - SubMethod() [02.2] - [00.5]: SubMethod Step 5
2024-07-17 16:50:58.319 [10.6] - MyTest2() [07.7] - SubMethod() [03.1] - [00.9]: - End -
2024-07-17 16:50:58.319 [10.6] - MyTest2() [07.7] - [00.0]: - End -
2024-07-17 16:50:58.320 [10.6] - TestCleanup() [00.0] - [00.0]: - Start -
2024-07-17 16:50:58.680 [11.0] - TestCleanup() [00.3] - [00.3]: TestCleanup Step 1
2024-07-17 16:50:59.073 [11.4] - TestCleanup() [00.7] - [00.3]: TestCleanup Step 2
2024-07-17 16:50:59.880 [12.2] - TestCleanup() [01.5] - [00.8]: TestCleanup Step 3
2024-07-17 16:51:00.306 [12.6] - TestCleanup() [01.9] - [00.4]: TestCleanup Step 4
2024-07-17 16:51:00.442 [12.7] - TestCleanup() [02.1] - [00.1]: TestCleanup Step 5
2024-07-17 16:51:01.299 [13.6] - TestCleanup() [02.9] - [00.8]: - End -