[open] Presentation time issues using canvas.image() in opensesame v27

Michif

Hi,

I am experiencing some issues concerning the presentation time of pictures that are rapidly presented one after the other. I am running an attentional blink experiment which presents 17 pictures in a row, each for 100 ms.

Although sleep time between the presentation of each canvas (containing a single picture) is 100ms, the whole sequence needs 3,5-3,7s to run through (more than 200ms per picture). The problem occurs in every trial also the very first, which has led me to the conclusion that it might not be solved by deleting all canvas after each trial. Strangely enough, this problem only occurs in the newly released version 27 (but also on the development version 22), NOT however in the old version v26.

I always use the psychopy engine and preload the images in the prepare phase (thus only use the .show function 17 times using a for-loop in the run phase). It is maybe also important to note that the images are not loaded into the file pool but instead a called via their original path.

Does anyone have an idea why this happens only in the new version and or have an advice how to solve it?

lvanderlinden

Hi Michel,

Would it perhaps be possible to upload your experiment? Although your explanation is very clear and obviously rules out some possibilities, it is still a bit difficult to find out what might be causing the delay without seeing the experiment.

Best wishes,

Lotje

Michif

Sure!

The prepare phase for the path attachment is a little bit crowded/overly nested. But in a nutshell it produces a list of canvas', each loaded a single picture from a path depending on the condition and the variables defined as in the block loop.


Prepare-phase

path = []

exp.canvas_pictures = range(17)

for i in range(17):

    exp.canvas_pictures[i] = self.offline_canvas()

    # distractor and target path definition with if statements just like the neutral trial

    # neutral

    else:

        path.append(os.path.normcase(os.path.join(exp.experiment_path,'pictures','landscape/')) + trial_pictures_list[i])

    exp.canvas_pictures[i].image(path[i])

    # Save the path

    exp.set("path"+str(i+1),path[i])

The run phase then loops through the canvas list and shows each item for 100 ms.


Run Phase

for img in exp.canvas_pictures:

    img.show()

    exp.sleep(100)

If I calculate the time of just the for loop in the run phase my subjective feeling that each picture is presented too long in only the latest version of OpenSesame is confirmed. Also sometimes I get weird trials in which only the very first picture lags (presented slightly longer than the other 16). However, I can't reproduce that error at the moment.

Thanks for the help!

EDIT: I reduced the code to make it more readable.

sebastiaan

Hi Michel,

You're code looks fine, but I was wondering: How do you check the presentation time? It's probably best to store the timestamps returned by img.show() in a list, and print them out afterwards. It could very well be that presentation is indeed slow, but then we know exactly what we're talking about:

l = []
for img in exp.canvas_pictures:
    t = img.show()
    l.append(t)
    exp.sleep(100)
for t in l:
    print t

Btw, the reason for storing the timestamps in a list first, rather then printing them out directly, is that printing to the debug window causes a slight delay in itself.

Cheers!

Michif

Hi sebastiaan,

I actually deleted the time check lines, since I included them only for debugging reasons. My assumption was however not entirely based on the values but also on the mere perception when starting the same code in either the v26 or v27. Here is what I did to check the time:

import time

t = time.time()

for img in exp.canvas_pictures:

    img.show()

    exp.sleep(100)

elapsed = time.time() - t

print elapsed

I am aware that there are delays in the presentation times between trials as well as when started in different version which might be entirely due to the print function. However, the pattern appears very distinct:

v26 - mean after 10 trials: 1850ms (around 110ms for each picture)

v27 - mean after 10 trials: 3600ms (around 210ms for each picture)

...both with low variability (around 100-200ms). I might check for more trials in a row.

This in combination with my subjective experience (which occurred before I checked the objective presentation times) gives me the impression that the timing is really not correct.

I will quickly run with your code and update this post.


Edit:

Ok, now I just got these weird fluctations again. But see yourself:
Here the times for the first 17 pictures in v26 (follow up trials are comparable):

7583.10036611

7699.77944124

7816.4303005

7933.09903912

8049.76302854

8166.4314878

8283.09603595

8399.759746

8516.52765924

8633.11677881

8749.75562537

8866.43777352

8983.09198515

9099.75625394

9216.42275764

9333.09456928

9449.75632378

Looks like decent ~110 ms steps.


And for v27 the first 17:

8816.39091002

8933.05462007

9049.72056504

9166.38930367

9283.06307087

9399.72175235

9516.38602113

9633.05001055

9749.72461584

9866.38190049

9983.05482959

10099.715746

10216.3811322

10333.0470772

10449.7146984

10566.3828783

10683.0474264

Also, decent ~110ms in the first two trials.


But then in the third trial:

20916.308637

21116.1312401

21316.1460465

21516.1924211

21716.1421354

21916.2256656

22116.0884973

22316.194656

22516.1778941

22716.2524846

22916.1555449

23116.0644719

23316.1114052

23516.1496782

23716.0831893

23916.1927005

24116.1385036

Now we got stable 200ms for each picture. Looks like some memory issue or what could be the reason why the times change all of the sudden? Note that the time have almost NO variation anymore (only for the first picture)! The same in the upcoming trials.
Also, I rechecked with my old printing time attemps: It looks like my initial thought of having a comparable variation of 210ms in the new OpenSesame versions, was basically also exactly 200ms except for the first trial which is apparently even slower than the subsequent 16 pictures and therefore reducing the overall time to just a little bit more than 200ms per picture.

sebastiaan

You're probably right, I'm not questioning that, but the code I posted potentially gives more insight, because it logs the timestamp for every image. Could you please run that and post the results? Perhaps you could try it with sequences of varying lengths (say with 1, 4, 8, and 16 images), to see if memory load might be an issue.

Michif

Short update:

I ran it with 1,4,8,16. The pattern is always the same now. It always works fine the first 2 times I run it. But as soon as the third trial starts the presentation times start to lag. Also when I stop the script and restart it, the problem persists and presentation times directly lag in the first trial. Only a restart of the program solves the problem then.


I just ran more thorough tests. The longer I keep on running the experiment with the lag, the slower the whole computer appears to become. After about 18-20 trials with 8 pictures, the program hardly reacts, and even if I press esc and close the program the computer works only slow. A new start of the program then quickly results in a Visual C++ Runtime Library error of opensesame.exe.

Maybe memory overload? The latter problem btw, needs more trials to occur when I only work with 1 or 2 pictures in each trial.

sebastiaan

Hi Michel,

Right, I see. Indeed, there is a clear and consistent slowdown.

The ITIs for the first trials are exactly 116.66ms, which is what you would expect given a 100ms sleep on a 60Hz monitor (where each cycle is 16.66Hz). If you want to get an ITI of 100ms, you should use a slightly shorter sleep, say 90ms. For a short discussion about this (which might not be intuitively obvious), see this post: http://www.cogsci.nl/forum/index.php?p=/discussion/comment/1054#Comment_1054

But that's not the main issue, of course. I suspect that the memory of the graphics card fills up. Once memory is full, PsychoPy can no longer pre-load the images and a pre-load delay is added to the presentation time (I think). This could be a bug in PsychoPy/ PyOpenGL (which have been updated since the 0.26 package), it might be an issue in your experiment, or perhaps a combination of both. There haven't been any significant changes in the psycho back-end itself, since 0.26.

You could do a number of things:

• First check if there is something in your code that could explain why memory fills up. The most obvious candidate is the use of the global keyword, especially in combination with a canvas.
• Switch to another back-end, if this is possible (you might rely PsychoPy-specific functions, of course).
• Rewrite the presentation code, so that you take the time required by c.show() into account:

[pastebin:T9JVwGCL]

I'm not sure how keen you are to get to the bottom of this, but you could see what happens if you downgrade PsychoPy to the version that came with OpenSesame 0.26 (you can check by running modules() in the debug window). To downgrade, you can simply replace the psychopy sub-folder of OpenSesame with the folder from the PsychoPy source: http://code.google.com/p/psychopy/downloads/list

If this resolves the issue, then we could consider reporting it to the PsychoPy developers. If it doesn't than the problem is elsewhere.

Cheers!

Michif

Hey sebastiaan,

some interesting news: First, the backend indeed solves the problem. No problems with e.g. legacy. The other interesting news is that with my code even when reduced to this bit:

l = []

for i in range(17):

    t = exp.canvas_pictures[i].show()

    l.append(t)

    exp.sleep(100)

for t in l:

    print t

... in the run phase, the problem occurs. However when I simply copy pasted yours, the problem does not occur that much. However, there are still changes in the time. Sometimes it jumps between pictures from 100ms to 200ms (or something in between), but these jumps rarely occur! As you can see in my first post I also used a comparable loop structure like you did in my first attempt as compared to the MATLAB-like i-iteration structure I used in my last attempt. So that's probably not it (would have surprised me anyways. So it basically boils down to fluctuations in the .show time "lag".

Also: Sure, I want to get to the bottom of this problem. So your suggestion is now to downgrade the psychopy engine and rerun the stuff in order to check whether they made some changes that caused this problem?

Cheers, and thanks for the help Sebastiaan!


Edit: example first three trials ( I marked the jumps) :

first trial:

9099.72412695 --> small jump

9182.8746391

9282.9186391

9382.94783276 --> small jump

9499.73027298

9599.71923806

9699.71770155

9799.71923806

9899.71546663

9999.72259044

10099.7135111

10199.7116952

10299.7140698

10399.7122539

10499.7143492

10599.7108571

10699.712673

second trial:

13516.3600402

13616.3562687

13716.3625545

13816.3540338

13916.3561291

14016.3559894

14116.3550116

14216.3638116

14316.3508211

14416.3498433

14516.3485862

14616.3481672

14716.3524973

14816.3531957

14916.3485862

15016.3492846

15216.3585037 --> bigger jump

third trial:

18716.3298687

18816.1730052

18916.2346052

19016.2079259

19116.2234306

19216.241729

19316.2583513

19416.226364

19516.2438243

19616.2428465

19716.2192402

19816.2403322

19916.2304148

20016.2389354

20116.2225925

20216.259329

20316.212256

sebastiaan

However when I simply copy pasted yours, the problem does not occur that much. However, there are still changes in the time. Sometimes it jumps between pictures from 100ms to 200ms (or something in between), but these jumps rarely occur!

Good! The script basically throttles the presentation, so that it doesn't go too fast. But when canvas.show() by itself takes longer than the intended delay, there will still be timing glitches, of course. I would definitely double check on the PC that you intend to use for actual testing to see how it goes there. If it's a very fast PC the timing might be perfect, if it's a very slow PC you might see substantial glitches.

So your suggestion is now to downgrade the psychopy engine and rerun the stuff in order to check whether they made some changes that caused this problem?

Yes, exactly. It's very puzzling that this problem didn't occur before (the results from 0.26 and 0.27 are from the same computer, right?), so there must be a regression somewhere.

Michif

Allright,

I'll check it as soon as I got time.
For the moment, your solution with subtracting the time needed for the show function, seems a decent temporary solution, right?
Thanks for the support!