Log Time stamps vs. time duration

Technical
1

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

Thanks
The

1 Like
2

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.

3 Likes
3

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?

4

@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
5

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.

6

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