Log Time stamps vs. time duration

Looking at the time stamps of 1) and 2) below, my quick calculation tells me
that it takes approx. 1 milisec for scpi-cmd: CAL? to return.
But it does not fit well with the duration [957 s] ~16 minutes
(which fits well with our expectation that calibration operation takes that long time)

Can you explain the beblow time stamps?

  1. 11:51:35.412 VXT2 Sec SCPI >> :CAL? [957 s]
  2. 11:51:35.413 VXT2 Sec SCPI << 0


1 Like

Hi @the.dao,

The time stamp on the left is when the message was logged, while the duration on the right is the duration which it took.

When you see square brackets e.g [957 s], you should count backwards from when the message was logged, not forward.


If β€œCAL?” and the result are both logged after command is finished --> Then this means that i dont have a log entry of the last query sent in the case that OpenTap shuts completly down during execution of the command, or?

@LXuser the execution and logging are on separate threads. You may even notice in some cases if you have a short test plan with lots of logging (or other results publishing) occurring that these stay open longer. If you force kill the entire process though, then yes there is a chance you could miss some stuff.

1 Like

I meant a shutdown of OpenTap in case of an Exception in a plugin.
Then i would not know which function created the exception if the start of it did was not logged yet.

The exeception will be passed to the log on a separate thread, so it should still be logged in all causes outside of catastrophic crashes. Which would be the same as most logging systems.

1 Like