Logging Data – Not as simple as it seems

For the upcoming streaming telemetry feature of the KSA Flight Tracker, not all the data I wanted to log was available via mods like VOID and Graphotron, so I had to turn to KOS to get the rest of it. I wanted to log new data every second, but my original method produced inaccurate results that forced me to re-think how program execution can affect time.

My first attempt went (basically) like this:

// a script trigger action group would switch this to false to exit
set running to true.
until not running {
  log floor(time:seconds) to Telemetry. // with other data not shown here
  wait 1.
}.

Seemed simple enough – write data to the file, including the whole number of seconds since the start of the game, wait one second and then log another line of data. However when I looked at the results of the log file I ended up with this:

52559995
52559996
52559997
52559999
52560000
…
52560014
52560015
52560017
52560018
52560019
…
52560049
52560050
52560051
52560053
52560054

See the problem? If not look again – the time stamp skips a second every so often. I can’t have that – each time stamp is for a record and the database from which the telemetry is read needs to maintain a consistent amount of time between records, in this case one second. So, not really thinking about it I figured instead I would do this:

set currTime to floor(time:seconds).
until not running {
  log currTime to Telemetry.
  set currTime to currTime + 1.
  wait 1.
}.

Now I’m guaranteed that each time stamp will be one second greater with no skipped seconds in between. However this time when I compared time stamps from the telemetry to events in the video capture I made of the launch they failed to match up after a couple of seconds into the ascent. The log shows that MECO happened at 10:12:14, but when I go to that point in the video capture the game time reads 10:12:18. When I run out of fuel a few minutes into the launch, the telemetry log data tells me this happened at 10:14:34 but when I got to that event in the video and look at the game clock it reads 10:14:51. A check through the time stamps shows no skips.

…??

Well, it was late so after sleeping on it and coming back to it the next day (always a good tactic) I realized my second attempt hadn’t addressed the underlying problem:

wait 1.

Here’s what was going on. Say the program began at 52560049.5875943 (seconds since the game start). It runs through the code and gets to the wait statement but during execution the game time has advanced to 52560049.6284095. So it waits until 52560050.6284095, runs the code real quick but still time has passed so now it is 52560050.7846532 when we reach the wait command so the program pauses until 52560051.7846532. Eventually the time will creep forward enough so that you lose an entire second to processing the code. Then two seconds, then three… the log time therefore appears to advance faster than the game time, which is why my log events showed things happening sooner with greater discrepancy as time went on.

I could have interpreted this was happening from the original implementation if I had thought about it more. So, the solution:

until not running {
  set currTime to floor(time:seconds).
  log currTime to Telemetry.
  wait until time:seconds - currTime > 1.
}.

This ensures that no matter how many milliseconds it takes the code to run, it will always do it again at the start of the next second, not one second after the code has reached the end of its loop. Now I have accurate log data. Huzzah!