Spikes in Elapsed Time (Variation in Code Performance)

[SB_123]

I am evaluating the performance (elapsed time) of the producer loop (in Consumer-Producer Architecture), and the producer is an independent loop. It does not have a dependency on other codes in the program except UI events (e.g. START, STOP, and VI Exit) will have an impact on the state diagram of the producer loop. I have included the Producer Loop Architecture in the attachment. In the producer loop, if there is no Error and user have not pressed START button, the state machine stays in EVENT MONITOR state, and the performance chart attached is the elapsed time for the EVENT Monitor only. And, the condition during obtaining above data was: NO UI EVENT, NO ERROR, CURRENT STATE --> EVENT MONITOR. 

It is surprising to see some spikes in the chart above. Most of the time the elapsed time for EVENT Monitor for above specified condition is around 10-12 ms, but few spikes were observed randomly. I am not sure what is causing these spikes and I do not understand why I am seeing spikes since the same code (that is independent) is running all the time.

The complete application code is large and uploading all 20-30 VIs might not help. Therefore I am taking snapshot of the code that was tested. 

"Producer Loop Code_Event Monitor.PNG" is the code that is being measured or evaluated. It consists of following three sub-VIs

a. MS Time String

b. CNDTL SAVE TO FILE

    This is simple code consisting of OPEN FILE, WRITE to File, CLOSE FILE operations.

c. EVENT Monitor

    This SubVI takes in current UI Events (default: No UI Event) and outputs the next state for the producer state machine. It is a simple case structure (nested for No_Event) code.

    Event_Handler_UI.png is the Front panel of this Sub-VI.

    Event_Handler_BlockDiagram.png shows the code for "No_Event" case and consists of nested Case structure. Other cases of nested case structure do not have any additional code except      "Next State" enum. Other cases of top level Case Structure (START, STEP, VI_EXIT) also only have "State" enum which is the next state output for the producer loop.

Therefore, the code looks straight forward and is simple. However, I do not understand why is there spike in the performance. I am looking for further help on troubleshooting or understanding the spikes in elapsed time.

Thank you 

[Frozen]

My first guess... You are using a Windows OS.

If you want more consistent timing you will want to investigate real-time OS'es

[SB_123]

Yes, I am using Windows OS. Can you please explain why Windows OS might cause this?

[Frozen]

Windows has a lot of back ground processes that may cause interruptions that you are experiencing, such as networking and virus scanners, and email applications, to name a few. All of them need *some* processing time which implies that your process must wait. It could be a little bit or a lot.

[Kevin_Price]

And FWIW, the timing variation you showed looks more or less typical to my eye.  The vast majority of iterations fall in a narrow band of +/- a handful of msec.  But somewhat regularly you get interruptions measured in the 10's of msec.  And once in a while you may get even longer ones.   That falls right in line with a number of my own observations over the years.

-Kevin P

[santo_13]

Just reiterating the answers you already got so far, this is the reality of a non-deterministic OS where the OS will not guarantee a time to complete the execution, for example, if you ask for elapsed time to wait x seconds but the OS does not guarantee to wait x seconds, rather it will "try" to wait x seconds, if it gets busy or stuck doing something else, it cannot complete the wait operation in x seconds.

This is one of the important reasons for the existence of an RTOS which is deterministic. If your application is affected by this non-deterministic timing then you have chosen an incorrect target OS.

To elaborate, Windows, Linux, and macOS, all are consumer targetted OS, which means, for instance, if opening Excel takes a few minutes longer than typical, it does not result in a catastrophic result. But you cannot use these OS in mission-critical applications such as controlling a power plant or controlling an aircraft or controlling a piece of medical equipment.

[altenbach]

---

@SB_123 wrote:

The complete application code is large and uploading all 20-30 VIs might not help. Therefore I am taking snapshot of the code that was tested. 

"Producer Loop Code_Event Monitor.PNG" is the code that is being measured or evaluated. It consists of following three sub-VIs

a. MS Time String

b. CNDTL SAVE TO FILE

    This is simple code consisting of OPEN FILE, WRITE to File, CLOSE FILE operations.

c. EVENT Monitor

---

So you have code that does these three things and are surprised that they don't execute in predictable time? Why do you have to open-write-close the file with every iteration?  From a simplified view, a drive is a shared sequential device and it can only do one thing at any given time (well the drive caching is quite advanced, but it still needs to protect processes from each other). Also open and closing a file involves some effort. I would bet that if you would do the file IO asynchronously and also open the file once and close at the very end, things would smooth out. Windows is of course not perfect for this, but I am sure you could rearchitect it for much better predictability.

As has been said, we don't work well with a pile of truncated code pictures. Too many things get lost in translation. If you could reduce it to a simple demo that still shows the problem, we could be much more specific and helpful.

Also note that the "high resolution relative seconds" returns relative seconds (duh!), so naming the formatted output "millisecond timer value" is very confusing. Are you calculating dt from adjacent column values in the file?

[SB_123]

@santo_13

Thanks for the great explanation.

[SB_123]

@altenbach

Thank you for your feedback. I will reduce the code to simple demo and post it later.

In regards to opening and closing file iteratively, I understand the implications but I am logging events in the critical sections of the code for debugging purposes. I am disabling these logs in final production release but keeping them during production test phase so that it will be easier for me to debug when an error occurs. Therefore, opening and close file resources in main VI was not helpful to keep code clean and organized. Therefore, to clean up the block diagram I included the operation of opening and closing in the subVI so that I can reuse the code.

In regards to "high-resolution relative seconds", it was a typo. I was using a millisecond timer first and later replaced it but missed renaming it. 

[altenbach]

---

@SB_123 wrote:

Therefore, to clean up the block diagram I included the operation of opening and closing in the subVI so that I can reuse the code.. 

---

You can still rearchitect your saving code into a state machine that can open the file on INIT (or "first call?"), and keep it open, then append to it in the WRITE (default) state, keeping the file ref in an uninitialized shift register.