Merge pull request #73 from drammock/loggingFixes

Logging fixes & time corrections for win.flip(), import errors for missing underscores on utils

expyfun/_create_system_config.py

@@ -7,7 +7,7 @@
 
 import logging
 
-from .utils import set_config, verbose_dec
+from ._utils import set_config, verbose_dec
 
 logger = logging.getLogger('expyfun')
 

expyfun/_experiment_controller.py

@@ -14,6 +14,7 @@
 prefs.general['audioLib'] = ['pyo', 'pygame']
 prefs.general['audioDriver'] = ['jack', 'portaudio']
 from psychopy import visual, core, event, sound, gui, monitors, misc
+from psychopy import clock as psyclock
 from psychopy.data import getDateStr as date_str
 from ._utils import (get_config, verbose_dec, _check_pyglet_version, wait_secs,
                      running_rms, _sanitize, psylog)
@@ -140,6 +141,10 @@ def __init__(self, exp_name, audio_controller=None, response_device=None,
 
         # set up timing
         self._master_clock = core.MonotonicClock()
+        self._time_corrections = dict()
+        flip_fun = visual.window.logging.defaultClock.getTime
+        self._time_correction_fxns = dict(flip=flip_fun)
+        self._get_time_correction('flip')
 
         # dictionary for experiment metadata
         self._exp_info = {'participant': participant, 'session': session,
@@ -438,7 +443,10 @@ def flip_and_play(self):
         if self._on_next_flip is not None:
             for function in self._on_next_flip:
                 self._win.callOnFlip(function)
-        self._win.flip()
+        # self._win.flip() returns psychopy.clock.monotonicClock.getTime()
+        flip_time = self._win.flip() + self._get_time_correction('flip')
+        self.write_data_line('flip & play', flip_time)
+        return flip_time
 
     def flip(self):
         """Flip screen, then run any "on-flip" functions.
@@ -848,6 +856,25 @@ def write_data_line(self, event_type, value=None, timestamp=None):
             self._data_file.write(ll)
             self._data_file.flush()  # make sure it's actually written out
 
+    def _get_time_correction(self, clock_type):
+        """Clock correction (seconds) for win.flip().
+        """
+        other_time = self._time_correction_fxns[clock_type]()
+        start_time = self._master_clock.getTime()
+        time_correction = start_time - other_time
+        if clock_type not in self._time_corrections:
+            self._time_corrections[clock_type] = time_correction
+
+        if not np.allclose(self._time_corrections[clock_type], time_correction,
+                           rtol=0, atol=10e-6):
+            psylog.warn('Expyfun: drift of > 10 microseconds between '
+                        '{} clock and EC master clock.'.format(clock_type))
+        psylog.debug('Expyfun: time correction between {} clock and EC master '
+                     'clock is {}. This is a change of {}.'
+                     ''.format(clock_type, time_correction, time_correction -
+                               self._time_corrections[clock_type]))
+        return time_correction
+
     def wait_secs(self, *args, **kwargs):
         """Wait a specified number of seconds.
 

expyfun/_eyelink_controller.py

@@ -20,7 +20,7 @@
     import pylink
 except ImportError:
     pylink = None
-from .utils import get_config, verbose_dec
+from ._utils import get_config, verbose_dec
 
 eye_list = ['LEFT_EYE', 'RIGHT_EYE', 'BINOCULAR']  # Used by eyeAvailable
 

expyfun/_input_controllers.py

@@ -6,10 +6,11 @@
 # License: BSD (3-clause)
 
 import numpy as np
+from functools import partial
 from psychopy import event
 from psychopy import clock as psyclock
 
-from ._utils import wait_secs, psylog
+from ._utils import wait_secs
 
 
 class BaseKeyboard(object):
@@ -35,8 +36,9 @@ def __init__(self, ec, force_quit_keys):
         self.ec_close = ec.close  # needed for check_force_quit
         self.force_quit_keys = force_quit_keys
         self.listen_start = None
-        self.time_correction = None
-        self.time_correction = self._get_time_correction()
+        ec._time_correction_fxns['keypress'] = self._get_keyboard_timebase
+        self.get_time_corr = partial(ec._get_time_correction, 'keypress')
+        self.time_correction = self.get_time_corr()
 
     def _clear_events(self):
         """Clear all events from keyboard buffer.
@@ -56,7 +58,7 @@ def _get_keyboard_timebase(self):
     def listen_presses(self):
         """Start listening for keypresses.
         """
-        self.time_correction = self._get_time_correction()
+        self.time_correction = self.get_time_corr()
         self.listen_start = self.master_clock.getTime()
         self._clear_events()
 
@@ -124,24 +126,6 @@ def check_force_quit(self, keys=None):
             self.ec_close()
             raise RuntimeError('Quit key pressed')
 
-    def _get_time_correction(self):
-        """Clock correction (seconds) between clocks for hardware and EC.
-        """
-        other_clock = self._get_keyboard_timebase()
-        start_time = self.master_clock.getTime()
-        time_correction = start_time - other_clock
-        if self.time_correction is not None:
-            if not np.allclose(self.time_correction, time_correction,
-                               rtol=0, atol=10e-6):
-                psylog.warn('Expyfun: drift of > 10 microseconds between '
-                            'system clock and experiment master clock.')
-            psylog.debug('Expyfun: time correction between system clock and '
-                         'experiment master clock is {}. This is a change of '
-                         '{} from the previous value.'
-                         ''.format(time_correction, time_correction -
-                                   self.time_correction))
-        return time_correction
-
     def _correct_presses(self, pressed, timestamp, relative_to):
         """Correct timing of presses and check for quit press"""
         if len(pressed):

expyfun/_tdt_controller.py

@@ -8,7 +8,7 @@
     connect_rpcox, connect_zbus = None, None
 from psychopy import logging as psylog
 
-from .utils import get_config, wait_secs
+from ._utils import get_config, wait_secs
 from ._input_controllers import BaseKeyboard
 
 

expyfun/_trigger_controllers.py

@@ -8,7 +8,7 @@
 import platform
 from psychopy import parallel
 
-from .utils import wait_secs, verbose_dec, psylog
+from ._utils import wait_secs, verbose_dec, psylog
 
 
 class PsychTrigger(object):

expyfun/_utils.py

@@ -388,6 +388,9 @@ def set_config(key, value):
         json.dump(config, fid, sort_keys=True, indent=0)
 
 
+###############################################################################
+# MISC
+
 def _check_pyglet_version(raise_error=False):
     """Check pyglet version, return True if usable.
     """

expyfun/tests/test_experiment_controller.py

@@ -4,7 +4,7 @@
 from numpy.testing import assert_allclose
 
 from expyfun import ExperimentController, wait_secs
-from expyfun.utils import _TempDir, interactive_test, tdt_test
+from expyfun._utils import _TempDir, interactive_test, tdt_test
 
 temp_dir = _TempDir()
 std_args = ['test']  # experiment name

expyfun/tests/test_eyelink_controller.py

@@ -1,8 +1,6 @@
 from nose.tools import assert_raises, assert_true
 from expyfun import EyelinkController, ExperimentController
-from expyfun.utils import _TempDir
-
-from expyfun.utils import requires_pylink
+from expyfun._utils import _TempDir, requires_pylink
 
 std_args = ['test']
 temp_dir = _TempDir()

expyfun/tests/test_logging.py

@@ -1,6 +1,6 @@
 import os
 
-from expyfun.utils import _TempDir, tdt_test
+from expyfun._utils import _TempDir, tdt_test
 from expyfun import ExperimentController
 
 tempdir = _TempDir()

expyfun/tests/test_utils.py

@@ -2,7 +2,7 @@
 import os
 import warnings
 
-from expyfun.utils import get_config, set_config, deprecated
+from expyfun._utils import get_config, set_config, deprecated
 
 
 def test_config():