# Log Time stamps vs. time duration **URL:** \ **Category:** Technical\ **Tags:** ks8400-editor\ **Created:** [December 3, 2020, 12:43pm UTC](https://forum.opentap.io/t/log-time-stamps-vs-time-duration/163 "2020-12-03T12:43:00Z")\ **Posts on this page:** 6\ **Page:** 1
**Author:** ![the.dao](https://avatars.discourse-cdn.com/v4/letter/t/b2d939/32.png) [@the.dao](https://forum.opentap.io/u/the.dao)\ **Post date:** [December 3, 2020, 12:43pm UTC](https://forum.opentap.io/t/log-time-stamps-vs-time-duration/163/1 "2020-12-03T12:43:00Z")
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 ---
**Author:** ![rolf\_madsen](https://avatars.discourse-cdn.com/v4/letter/r/43a26b/32.png) [@rolf\_madsen](https://forum.opentap.io/u/rolf_madsen)\ **Post date:** [December 3, 2020, 1:05pm UTC](https://forum.opentap.io/t/log-time-stamps-vs-time-duration/163/2 "2020-12-03T13:05:17Z")
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. ---
**Author:** ![LXuser](https://sea2.discourse-cdn.com/flex020/user_avatar/forum.opentap.io/lxuser/32/145_2.png) [@LXuser](https://forum.opentap.io/u/LXuser)\ **Post date:** [December 4, 2020, 8:19am UTC](https://forum.opentap.io/t/log-time-stamps-vs-time-duration/163/3 "2020-12-04T08:19:32Z")
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? ---
**Author:** ![brennen\_direnzo](https://sea2.discourse-cdn.com/flex020/user_avatar/forum.opentap.io/brennen_direnzo/32/6_2.png) [@brennen\_direnzo](https://forum.opentap.io/u/brennen_direnzo)\ **Post date:** [December 4, 2020, 3:27pm UTC](https://forum.opentap.io/t/log-time-stamps-vs-time-duration/163/4 "2020-12-04T15:27:08Z")
@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. ---
**Author:** ![LXuser](https://sea2.discourse-cdn.com/flex020/user_avatar/forum.opentap.io/lxuser/32/145_2.png) [@LXuser](https://forum.opentap.io/u/LXuser)\ **Post date:** [December 4, 2020, 3:51pm UTC](https://forum.opentap.io/t/log-time-stamps-vs-time-duration/163/5 "2020-12-04T15:51:42Z")
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. ---
**Author:** ![brennen\_direnzo](https://sea2.discourse-cdn.com/flex020/user_avatar/forum.opentap.io/brennen_direnzo/32/6_2.png) [@brennen\_direnzo](https://forum.opentap.io/u/brennen_direnzo)\ **Post date:** [December 4, 2020, 3:54pm UTC](https://forum.opentap.io/t/log-time-stamps-vs-time-duration/163/6 "2020-12-04T15:54:23Z")
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.