[visionegg] optimizing my code since timing is a catastrophe

Dear Andrew
Thanks for the LPT hint. It works fine now.

Another things, before despairing completely and quitting all attempts
(my complete code is below):

I logged the time, each time I get to the 

for event in pygame.event.get(pygame.locals.MOUSEBUTTONDOWN): 
            if event.button == 1:
                response_log.append(VisionEgg.time_func() - trial_onset)
code.

CONCLUSION:
with 120 images (totally 16.4MB) loaded as textures before entering the
main loop, the timing with and without maxpriority is a catastrophe in
the following way:

the time between a mouse-event check and its next event-check, if and
only if the inner while loop is left due to make a swap() in the outer
while loop, is for several trials more than 100ms (if I don't restart
the computer in few case even more than 1sec)

see this log-file excerpt:

after a system restart:

______ all times in s ____________
<= 0.010: 18091456    
<= 0.020: 142    
<= 0.030: 4    
<= 0.040: 41    
<= 0.050: 63    
<= 0.060: 3    
<= 0.080: 2    
<= 0.1: 5    
<= 0.2: 3    means, 3x between 0.1 and 0.2 s
<= 0.4: 1    
<= 0.6: 0    
<= 0.8: 0    
<= 1: 0    
<= 2: 0    
<= 3: 0    
<= 4: 0    
<= 5: 0    
> 5: 0    ___________________________________

if the computer is not restarted:

______ all times in s ____________
<= 0.010: 17722917    
<= 0.020: 140    
<= 0.030: 5    
<= 0.040: 73    
<= 0.050: 31    
<= 0.060: 2    
<= 0.080: 4    
<= 0.1: 0    
<= 0.2: 4    
<= 0.4: 1    
<= 0.6: 0    
<= 0.8: 2    
<= 1: 0    
<= 2: 0    
<= 3: 1    
<= 4: 0    
<= 5: 1    
> 5: 0    


This means, that I cannot use the code as it is now, for any behavioral
experiments, since subjects show RT < 100ms. With the trials showing
even seconds between, it's even worse, since so I will miss
trigger-signals from the scanner

I don't know, where I loose this time, but I cannot imagine it is the 

    stimulus.parameters.texture = preloaded_texture_list[stim_index]
    screen.clear()
    viewport.draw()
    swap_buffers()

part (this is code from you, and is very fast)

but which commands are that slow? list-appends? Is there any-thing wrong
with not released memory (target class?), since the problems seem to
appear only with a large number of stimuli (> e.g. 20) not with few
stimuli and the worse, if the computer is not restarted before running
the code.

I attach you my code, just change the two paths and put some pictures
(>100) in the data_orig directory and a fixation cross or anything else
in the other directory

Thanks a lot for your help. I was already too happy in thinking I got it
to work..

Christoph

==== code ====
#!/usr/bin/env python

#This bypasses the VisionEgg.Core.Presentation class.  It may be easier
#to create simple experiments this way."""

import VisionEgg
from VisionEgg.Core import *
import pygame
from pygame.locals import *
from VisionEgg.Text import *
from math import *
from operator import mod
from operator import div
from random import *
import VisionEgg.Daq
from VisionEgg.DaqLPT import *
from VisionEgg.Textures import *

screen = get_default_screen()
screen.parameters.bgcolor = (0.0,0.0,0.0,0.0) # black (RGBA)

path =
"/home/christoph/work/programming/my_ve_projects/load_picture/data_orig/" #the 
path the images are in
fixation =
"/home/christoph/work/programming/my_ve_projects/load_picture/fixation_stimuli/fixation02.bmp"

photo = []
photoX = []

# present them in random order
for filename in os.listdir(path):
    photo.append(filename)
length = len(photo)
for stim_index in range(0, length):
    ran = randint(0, len(photo)-1)
    file = photo[ran]
    photoX.append(file)
    photo.pop(ran)

# Insert a fixation cross in front of the texture list
photoX.insert(0,fixation)
os.chdir(path)

num_images = len(photoX)
ratio = 4 #4 volumes equal one trial (one TR fixtion, 3 TRs stimulus)

# Create list of stimuli
preloaded_texture_list = [] # empty at first
for stim_index in range(num_images):
    # Read the texture file
    texture = Texture(photoX[stim_index])

    # Add to list of stimuli
    preloaded_texture_list.append( texture )

x = screen.size[0]/2 - preloaded_texture_list[0].size[0]/2
y = screen.size[1]/2 - preloaded_texture_list[0].size[1]/2
stimulus = TextureStimulus(on = 1,
                           texture = preloaded_texture_list[0],
                           size = preloaded_texture_list[0].size,
                           lowerleft=(x,y))
viewport = Viewport( screen=screen, stimuli=[stimulus] ) #does not
display the texture until viewport.draw() is called


# The main loop below is an alternative to using the
# VisionEgg.Core.Presentation class.

trial_log_list = []
trial_log = []
response_log_list = []
response_log = []        
  
swap_time = 0
stim_index = 0
trial_index = 0
trial_onset = 0 #the time, a stimulus is drawn (not fixation)
trigger_onset = 0 #the time, a trigger has been detected on the lpt
start_time = -1
trigger_counter = -1
loop_ctr = 0 #to check, whether the outer while loop is entered the
first time (log start_time)
trigger_armed = 1

timestamp = [] #for time loggging only
looptime = 0 #for time loggging only
last_time = VisionEgg.time_func()

while (not pygame.event.peek((QUIT,KEYDOWN))):
    # wait for mouse response and trigger on the parallel port
    while (not pygame.event.peek((QUIT,KEYDOWN))):
        # only during developing check timing accuracy
        actualtime = VisionEgg.time_func()
        looptime = (actualtime - last_time)*1000 #log in ms
        last_time = actualtime
        timestamp.append(looptime)
        #log the mouse response (which button, and RT)
        for event in pygame.event.get(pygame.locals.MOUSEBUTTONDOWN): 
            if event.button == 1:
                response_log.append(VisionEgg.time_func() - trial_onset)
                response_log.append('L') #left
            elif event.button == 3:
                response_log.append(VisionEgg.time_func() - trial_onset)
                response_log.append('R') #right
        # poll the LPT for the TTL trigger, sent by the MR scanner
        if trigger_counter == 3:
            trigger_counter = -1 #reset ctr, since 4 volumes equal one
trial (one TR fixtion, 3 TRs stimulus)
        input_value = raw_lpt_module.inp(0x379) & 0x20        # pin nr
12
        # if TTL signal on lpt, increment the index for the texture-list
        if input_value == 0x20 and trigger_armed == 1: 
            trigger_counter = trigger_counter + 1
            trigger_armed = 0 #don't increment the texture-index, until
a new trigger puls is received (TTL pulse ca. 50ms)
            if mod(trigger_counter,ratio) == 0: #0: draw fixation
                trial_index = trial_index + 1 #after the drawn fixation
cross, the next swap will draw a new stimulus
                stim_index = 0
                break #leave the loop and update the screen, drawing a
fixation cross (begin of a new trial-compound)
            if mod(trigger_counter,ratio) == 1: #1: draw stimulus
                stim_index = trial_index #has been incremented during
the previous fixation loop
                break #leave the loop and update the screen with the new
stimulus
        elif input_value == 0 and trigger_armed == 0:  #first lpt
poll-loop after the TTL signal has fallen from 1 to 0 (-> arm trigger)
            trigger_armed = 1

    # quit if all stimuli shown
    if trial_index == num_images:
        response_log_list.append(response_log) #append last response log
and quit
        break

    # draw the stimulus (during first loop: fixation)
    stimulus.parameters.texture = preloaded_texture_list[stim_index]
    screen.clear()
    viewport.draw()
    swap_buffers()
    swap_time = VisionEgg.time_func()
    
    if loop_ctr == 0: #first fixation shown
        start_time = swap_time

    # logging
    if stim_index > 0: 
        # log the stimulus with onset-time info
        trial_onset = swap_time #confusing: trial_onset is the time the
stimulus is drawn 
        trial_log = (stim_index, trial_onset - start_time,
photoX[stim_index]) #create next new log
        trial_log_list.append(trial_log) #append last log
        # log the mouse-response info
        if loop_ctr > 0: #1st loop: fixation; only after the first
stimulus, response makes sense
            response_log_list.append(response_log) #append last response
log (since we want only one response log per trial
        response_log = [] #clear response_log
        response_log.append(stim_index)
        response_log.append(photoX[stim_index])      

    loop_ctr = loop_ctr + 1

#end of the main loop


# write all log info to several files
# create a histogramm of the loop-repeats in ms
t10 = 0
t20 = 0
t30 = 0
t40 = 0
t50 = 0
t60 = 0
t80 = 0
t100 = 0
t200 = 0
t400 = 0
t600 = 0
t800 = 0
t1000 = 0
t2000 = 0
t3000 = 0
t4000 = 0
t5000 = 0
t6000 = 0
t7000 = 0
t8000 = 0
t9000 = 0
t10000 = 0
t11000 = 0
t12000 = 0
t13000 = 0
t14000 = 0
t15000 = 0
t16000 = 0
t17000 = 0
t18000 = 0
t19000 = 0
t20000 = 0
t30000 = 0
t40000 = 0
t50000 = 0
t100000 = 0
tt = 0

for x in timestamp: #all in ms (milliseconds!)
    if x <= 10:
        t10 = t10 + 1
    elif x <= 20:
        t20 = t20 + 1
    elif x <= 30:
        t30 = t30 + 1
    elif x <= 40:
        t40 = t40 + 1
    elif x <= 50:
        t50 = t50 + 1
    elif x <= 60:
        t60 = t60 + 1
    elif x <= 80:
        t80 = t80 + 1
    elif x <= 100:
        t100 = t100 + 1
    elif x <= 200:
        t200 = t200 + 1
    elif x <= 400:
        t400 = t400 + 1
    elif x <= 600:
        t600 = t600 + 1
    elif x <= 800:
        t800 = t800 + 1
    elif x <= 1000:
        t1000 = t1000 + 1
    elif x <= 2000:
        t2000 <= 2000
    elif x <= 3000:
        t3000 = t3000 + 1
    elif x <= 4000:
        t4000 = t4000 + 1
    elif x <= 5000:
        t5000 = t5000 + 1
    elif x > 100000:
        tt = tt + 1



f=open('/home/christoph/work/programming/my_ve_projects/load_picture/timing.txt',
 'w')
f.write('______ all times in s ____________' + '\n')
f.write("<= 0.010: %d    " % t10)
f.write('\n')
f.write("<= 0.020: %d    " % t20)
f.write('\n')
f.write("<= 0.030: %d    " % t30)
f.write('\n')
f.write("<= 0.040: %d    " % t40)
f.write('\n')
f.write("<= 0.050: %d    " % t50)
f.write('\n')
f.write("<= 0.060: %d    " % t60)
f.write('\n')
f.write("<= 0.080: %d    " % t80)
f.write('\n')
f.write("<= 0.1: %d    " % t100)
f.write('\n')
f.write("<= 0.2: %d    " % t200)
f.write('\n')
f.write("<= 0.4: %d    " % t400)
f.write('\n')
f.write("<= 0.6: %d    " % t600)
f.write('\n')
f.write("<= 0.8: %d    " % t800)
f.write('\n')
f.write("<= 1: %d    " % t1000)
f.write('\n')
f.write("<= 2: %d    " % t2000)
f.write('\n')
f.write("<= 3: %d    " % t3000)
f.write('\n')
f.write("<= 4: %d    " % t4000)
f.write('\n')
f.write("<= 5: %d    " % t5000)
f.write('\n')
f.write("> 5: %d    " % tt)
f.write('___________________________________' + '\n')
f.close()


f=open('/home/christoph/work/programming/my_ve_projects/load_picture/trial_log_file.txt',
 'w')
f.write('trial   onset_t         stim' + '\n')
f.write('______________________________' + '\n')

x = 0
while x < len(trial_log_list):
    y = 0
    while y < len(trial_log_list[x]):
        if (type(trial_log_list[x][y]) == types.FloatType):
            if y == 0:
                 f.write("%04.0f    " % trial_log_list[x][y])          
#trial index
            elif y == 1:                                           # y =
0: onset_time of the stimulus             
                f.write("    %010.2f    " % (trial_log_list[x][y] *
1000)) #onset time of the stimulus
            else:
                f.write("%010.2f    " % (trial_log_list[x][y] * 1000))
#RT
        else:
            f.write(str(trial_log_list[x][y]) + "  ")                 
#mouse response (left/right)
        y = y + 1
    f.write('\n')
    x = x + 1
f.write('______________________________' + '\n')
f.write('Remarks:' + '\n')
f.write('(i) onset_t: time of the stimulus onset relative to the first
volume of the scanner' + '\n')
f.close()


f=open('/home/christoph/work/programming/my_ve_projects/load_picture/response_log_file.txt',
 'w')
f.write('trial   stim          RT  button (L/R)' + '\n')
f.write('___________________________________________________________________________________'
 + '\n')

x = 0
while x < len(response_log_list):
    y = 0
    while y < len(response_log_list[x]):
        if (type(response_log_list[x][y]) == types.FloatType):
           if (y == 0):
                f.write("%04.0f    " % response_log_list[x][y])         
#trial index
           else:
                f.write("    %010.2f    " % (response_log_list[x][y] *
1000)) #RT
        else:
            f.write(str(response_log_list[x][y]) + " 
")                  #mouse response (left/right)
        y = y + 1
    f.write('\n')
    x = x + 1
f.write('___________________________________________________________________________________'
 + '\n')
f.write('Remarks:' + '\n')
f.write('(i) RT: reaction-time of the subject, measured relative to the
corresponding stimulus onset' + '\n')
f.close()







===================================================================================


-- 
Christoph Lehmann <lehmann@xxxxxxxxxxxx>
University Hospital of Clinical Psychiatry

======================================
The Vision Egg mailing list
Archives: http://www.freelists.org/archives/visionegg
Website: http://www.visionegg.org/mailinglist.html

Other related posts: