Elapsed Time While Running Test Plan & Test Steps

Hi,

I am developing an operator GUI. It works without a problem but I want to show the elapsed time on the GUI. I am starting a timer to show it on the screen there is no problem in that.

Still, I wanted to know if there is a built in method or property in OpenTap to get the elapsed time while plan is running. Same goes for test steps, currently I am starting a timer on the OfferBreak event to show test step’s elapsed time.

TestStepRun and TestPlanRun have Duration property but they are updated after step or plan is finished.

I would appreciate any help.

2 Likes

Hi @btyilmaz,

I suggest you add a “GuiResultListener” when you run the test plan, which can tell you when a test plan starts and stop. That will help you keep track of which steps are running and which has completed. Note that, because the UI thread usually runs in a different thread than the test plan, so something like ConcurrentDictionary is appropriate for keeping track of the started/finished step runs. Using Dictionary here can cause issues.

I have implemented this by updating the time roughly every frame. If you use WPF, you can use the System.Windows.Media.CompositionTarget.Rendering event.

4 Likes

Thanks for the suggestion. Would a ResultListener affect the performance of the test plan execution? It needs to be precise in the order of a few milliseconds. Which one is a better option? BreakOffered event or GuiResultListener?

So to answer your questions exactly:

  • It does not significantly affect the performance.
  • It is as precise as you can get - usually down to microseconds, but this can depend on the system.

There might be a short delay between the event occurring and the callback happening to the result listener and then again you would need to transfer the result to the GUI thread in order to notify the user.
I don’t know how fast those context switches can happen, but I am assuming this is also in the order of microseconds.

I would definitely try that first, we can cut off one context switch if needed, by using a slightly different API.

1 Like

Hi @rolf_madsen ,

Your suggestion solved my problem but I wondered how fast it can go and run a test plan with a log output step inside a repeat step with iteration count of 10000. Log output step lasts for approximately 20 microseconds. Then this warning: “Estimated processing time for result queue reached 3.6s (Limit is set to 3s in Engine.xml). Waiting for queue to be processed by GuiResultListener…” is shown in my log view. Our test plan is similiar to this structure but step inside the repeat lasts for 6-10ms.

To model the problem I created a test plan that consists of a repeat step and a child delay for operation. When the delay is greater than 1 ms there is no problem, but when it is getting lower than a ms, this warning is shown. I tried to run the same model plan in the PathWave editor and there is no problem. Well, I know that the problem is the GuiResultListener that I created, but I want this result listener to be as efficient as it can be so that we can use it in the future for other projects also.

Operations in the test step run start and complete are shown below. This is an ugly way of doing what I want but let me explain the code below. I hold all the test steps in the test plan inside a model list. My model, called TestStepTreeNode, contains duration&verdict etc. At the start of each step, a viewmodel that holds a timer is created and associated with the TestStepTreeNode. When the test step is completed the timer is stopped. I dont like this ugly code, so if you can point a direction how to implement a better solution it would be great.

OnTestStepRunStarted(object sender, Result_Listeners.TestStepRunStartedEventArgs e)
{
    System.Windows.Application.Current.Dispatcher.Invoke(DispatcherPriority.Send, new Action(() =>
    {
        var node = Plan.RootDescendents.FirstOrDefault(x => x.Id == e.TestStepRun.TestStepId);
        if (node is null) return;
        node.IsRunning = true;
        var viewModel = new StepRunDisplayTimerViewModel(e.TestStepRun, node);
        _runningSteps.Add(viewModel);
    }));
}

OnTestStepRunCompleted(object sender, TestStepRunCompletedEventArgs e)
{
    System.Windows.Application.Current.Dispatcher.Invoke(DispatcherPriority.Send, new Action(() =>
    {
        var vm = _runningSteps.FirstOrDefault(x => x.StepRun.TestStepId == e.TestStepRun.TestStepId);
        vm?.StopTimer();
        vm.TestStepTreeNode.IsRunning = false;
        _runningSteps.Remove(vm);
    }));
}

Edit: Something I forgot to mention, I am using the EventResultListener example and these methods are the methods that are invoked by those events.

OK, so it’s a good start!

The problem is caused by Dispatcher.Invoke actually being a very slow call in general. Mostly since it needs to do a two-way sync between the result listener and GUI thread. This can be fixed by making a things a bit more asynchronous. You can start by using BeginInvoke, but actually I’d suggest something else for optimal performance:

To get past the 1ms update rate, make a concurrent queue that you write the events to and process the queue from the UI thread.

For example, process the queue in an event handler for System.Windows.Media.CompositionTarget.Rendering.

Note, don’t attach too many of these event handler, maybe attach it on open and de-attach it on close, so you only ever have max 1 attached.

In you case, maybe 10-100 events will queue up, but processing those should be very fast.

Maybe as a last thing, if the queue gets too big, like at +1000 events, you could consider adding a delay in the result listener thread, just to avoid things hangs completely if it gets very busy.

I hope what I wrote makes sense, otherwise I can try to work on an example… :slight_smile:

1 Like

Thanks for the suggestions. I used Rendering event inside my viewmodel. I know how can I use it but I couldn’t understand how to create a queue. What will I store in the queue and where should I attach rendering event?

If you have time an example would be awesome :slightly_smiling_face:

2 Likes

Ok, so this is a bit longwinded, but it should have pretty good performance:

class OperatorUiResultListener : ResultListener
    {
        public enum EventType
        {
            StepStart,
            StepCompleted
        }
        
        ConcurrentQueue<(TestStepRun, EventType)> workQueue = new ConcurrentQueue<(TestStepRun, EventType)>();

        public override void Close()
        {
            while (workQueue.IsEmpty == false)
            {
                TapThread.Sleep(1);
            }
            base.Close();
            System.Windows.Application.Current.Dispatcher.Invoke(DispatcherPriority.Send,new Action(() =>
            {
                System.Windows.Media.CompositionTarget.Rendering -= CompositionTargetOnRendering;
            }));
        }
        public override void Open()
        {
            base.Open();
            System.Windows.Application.Current.Dispatcher.Invoke(DispatcherPriority.Send,new Action(() =>
            {
                System.Windows.Media.CompositionTarget.Rendering += CompositionTargetOnRendering;
            }));
        }
        void CompositionTargetOnRendering(object sender, EventArgs e)
        {
            List<(TestStepRun, EventType)> poppedElements = new List<(TestStepRun, EventType)>(); 
            while (workQueue.TryDequeue(out var thing) && poppedElements.Count < 100)
            {
                for (int i = 0; i < poppedElements.Count; i++)
                {
                    // if the step started and stopped before the UI got updated..
                    // just keep the last event.
                    if (poppedElements[i].Item1.Id == thing.Item1.Id)
                    {
                        poppedElements.RemoveAt(i);
                        break;
                    }
                }
                poppedElements.Add(thing);
            }
            foreach (var element in poppedElements)
            {
               // process events
                if (element.Item2 == EventType.StepStart)
                {
                    //var node = Plan.RootDescendents.FirstOrDefault(x => x.Id == e.TestStepRun.TestStepId);
                    //if (node is null) return;
                    //node.IsRunning = true;
                    //var viewModel = new StepRunDisplayTimerViewModel(e.TestStepRun, node);
                    //_runningSteps.Add(viewModel);
                }
                else
                {
                    //var vm = _runningSteps.FirstOrDefault(x => x.StepRun.TestStepId == e.TestStepRun.TestStepId);
                    //vm?.StopTimer();
                    //vm.TestStepTreeNode.IsRunning = false;
                    //_runningSteps.Remove(vm);
                }
            }
        }
        
        public override void OnTestStepRunStart(TestStepRun stepRun)
        {
            base.OnTestStepRunStart(stepRun);
            workQueue.Enqueue((stepRun, EventType.StepStart));
        }

        public override void OnTestStepRunCompleted(TestStepRun stepRun)
        {
            base.OnTestStepRunStart(stepRun);
            workQueue.Enqueue((stepRun, EventType.StepCompleted));
        }
    }
3 Likes

Thanks @rolf_madsen ! It is much better now. Although, still I have some problems with processing events but rest is solved thanks to you

2 Likes