Inconsistent timestamp while logging

[mape2k]

Hi all,

I have come across a problem concerning the timestamps in a log file that I want to use to monitor the position and view angle of a subject during an experiment.

At the beginning of the experiment, I am calling the logging function with vizact.ontimer(fs,function), with fs being the desired sampling frequency. When I use this method, I am not getting timestamps with equal time spans in the log file. It seems that the time spans vary about the given fs with +-10ms.
I am using datetime.datetime.now() to get the current time. Is there any other way of producing accurate time readings? I have read that datetime essentially uses time.time(), which is supposed to be the most accurate function in Python.

Here is an example for an fs = 10:

Timestamp, Position, View Angle
18:42:41:056,[0.000,1.820,-0.000],[-0.000]
18:42:41:166,[0.000,1.820,-0.000],[-0.000]
18:42:41:259,[0.000,1.820,-0.000],[-0.000]
18:42:41:368,[0.000,1.820,-0.000],[-0.000]
18:42:41:462,[0.000,1.820,-0.000],[-0.000]
18:42:41:556,[0.000,1.820,-0.000],[-0.000]
18:42:41:665,[0.000,1.820,-0.000],[-0.000]
18:42:41:758,[0.000,1.820,-0.000],[-0.000]
18:42:41:868,[0.000,1.820,-0.000],[-0.000]
18:42:41:961,[0.000,1.820,-0.000],[-0.000]
18:42:42:070,[0.000,1.820,-0.000],[-0.000]
18:42:42:164,[0.000,1.820,-0.000],[-0.000]
18:42:42:258,[0.000,1.820,-0.000],[-0.000]

Also, I am including a minimum working example:

from __future__ import division
import viz
import vizact
import viztask
import os
import datetime

class myTimer():

	def __init__(self,number,dateFormat,timeFormat):
		
		self.nr = number
		self.dateFormat = dateFormat
		self.timeFormat = timeFormat
	
	def time(self):
		
		self.curDateTime = datetime.datetime.now()
		self.curTime = self.curDateTime.strftime(self.timeFormat)
		if self.timeFormat == '%H:%M:%S:%f':
			self.curTime = self.curTime[:-3]
		return self.curTime


logTime = myTimer(1,'%d.%m.%Y','%H:%M:%S:%f')	

file = open('test.txt', 'w')	
	
def posLogger():
	
	curAngle = viz.MainView.getEuler()
	curPos = viz.MainView.getPosition()
	file.write('%s,[%0.3f,%0.3f,%0.3f],[%0.3f]\n' % 
	(logTime.time(),curPos[0],curPos[1],curPos[2],curAngle[0]))

# -----
# Start
# -----

fs = 10
print 1/fs
logTimer = vizact.ontimer((1/fs),posLogger)	
viz.go()

[sleiN13]

The timer function probably will only be called when the vizard rendering loop is in its update phase.

This means if the timer was suppose to run out but vizard is busy with rendering the scene or other code, it has to wait untill that part is finished.

This restriction is a consequence of the python interperter lock and there probably isn't a good solution for you problem because of it.

Also I believe that the time.clock() function is more precise it ofcourse doesn't give a date.

[mape2k]

Thanks for your reply!

Do you think the problem might also be reduced when I call the timer function in a new thread (i.e. viz. director(function))? Or would the vizard rendering loop still delay the output?

[farshizzo]

For high resolution timing values, you should use either viz.tick() or time.clock(). These functions will provide the number of seconds since the application started. If you need a high resolution representation of the actual time, then you can capture the current time at the beginning of your script and then add on the high resolution seconds to it at runtime. Here is an example:

import viz
import vizact
import datetime

viz.go()

# Get starting time and tick
startTime = datetime.datetime.now()
startTick = viz.tick()

def LogTime():

	# Add elapsed seconds to starting time
	curTime = startTime + datetime.timedelta(0,viz.tick()-startTick)
	print curTime.strftime('%H:%M:%S:%f')

vizact.ontimer(0.1, LogTime)

Keep in mind that writing to a file in the main rendering loop can cause drops in your framerate. You might want to consider moving your file writing code to a different thread.

[mape2k]

Thank you farshizzo for your detailed reply! I will try out your code as soon as possible and report back on the matter.