Canvas.Copy is taking too long to complete

Fri Apr 26 12:54:45 UTC 2013

Hi,
So, for anyone who'd like to test this. I use win7, 64bits (to do the coding
anyway), EP2.0.10.242. This is the full code of the experiment and should
work on any E-Prime with just a single inline bit in which you can paste the
following:

------------------------

Dim cnvs As Canvas 'the active display
Dim cnvsnext As Canvas 'the buffered canvas
Dim j As Integer
Dim clocktimes(1 To 100,1 To 4) As Long

Set cnvs = Display.Canvas
Set cnvsnext = Display.CreateCanvas()
sleep 8000 'this is required for early experiment timing errors

debug.print "*****WAIT BEFORE CNVSCOPY****"
For j = 1 To 100
	clocktimes(j,1) = clock.read	
	cnvsnext.Line random(0,100), random(0,100),  random(0,100),
random(0,100)
	clocktimes(j,2) = clock.read - clocktimes(j,1)
	display.waitforverticalblank
	clocktimes(j,3) = clock.read - clocktimes(j,1)	
	cnvs.copy cnvsnext	
	clocktimes(j,4) = clock.read - clocktimes(j,1)		
Next j

For j = 1 To 100
	debug.print "Trial " &CStr(j) & ": " & CStr(clocktimes(j,1)) & " " &
CStr(clocktimes(j,2)) & " " & CStr(clocktimes(j,3)) & " " &
CStr(clocktimes(j,4))
Next j
debug.print "Debug printing took " & CStr(clock.read -
(clocktimes(100,1)+clocktimes(100,4)))
For j = 1 To 100
	clocktimes(j,1) = clock.read	
	cnvsnext.Line random(100,200), random(0,100),  random(100,200),
random(0,100)
	clocktimes(j,2) = clock.read - clocktimes(j,1)
	cnvs.copy cnvsnext	
	clocktimes(j,3) = clock.read - clocktimes(j,1)		
	display.waitforverticalblank
	clocktimes(j,4) = clock.read - clocktimes(j,1)	
Next j
debug.print "*****WAIT AFTER CNVSCOPY****"
For j = 1 To 100
	debug.print "Trial " &CStr(j) & ": " & CStr(clocktimes(j,1)) & " " &
CStr(clocktimes(j,2)) & " " & CStr(clocktimes(j,3)) & " " &
CStr(clocktimes(j,4))
Next j

---------------------------

Apart from showing beautiful lines, it gives me the following info in the
debug output:

*****WAIT BEFORE CNVSCOPY****
Trial 1: 15854 1 7 24
Trial 2: 15878 2 17 33
Trial 3: 15912 1 16 33
Trial 4: 15945 1 16 33
Trial 5: 15978 2 17 33
Trial 6: 16012 1 16 33
Trial 7: 16045 1 16 33
Trial 8: 16078 1 17 33
Trial 9: 16111 2 17 34
Trial 10: 16145 1 16 33
Trial 11: 16178 1 17 33
Trial 12: 16211 2 17 34
Trial 13: 16245 1 16 33
Trial 14: 16278 1 17 33
Trial 15: 16311 2 17 34
Trial 16: 16345 1 16 33
Trial 17: 16378 2 17 33
Trial 18: 16411 2 17 34
Trial 19: 16445 1 16 33
Trial 20: 16478 1 17 33
Trial 21: 16511 2 17 34
Trial 22: 16545 1 16 33
Trial 23: 16578 1 17 33
Trial 24: 16611 2 17 34
Trial 25: 16645 1 16 33
Trial 26: 16678 2 17 33
Trial 27: 16711 2 17 34
Trial 28: 16745 1 16 33
Trial 29: 16778 1 17 33
Trial 30: 16811 2 17 34
Trial 31: 16845 1 16 33
Trial 32: 16878 1 17 33
Trial 33: 16911 2 17 34
Trial 34: 16945 1 16 33
Trial 35: 16978 1 17 33
Trial 36: 17011 2 17 34
Trial 37: 17045 1 16 33
Trial 38: 17078 2 17 33
Trial 39: 17111 2 17 34
Trial 40: 17145 1 16 33
Trial 41: 17178 1 17 33
Trial 42: 17211 2 17 34
Trial 43: 17245 1 16 33
Trial 44: 17278 1 16 33
Trial 45: 17311 2 17 34
Trial 46: 17345 1 16 33
Trial 47: 17378 1 16 33
Trial 48: 17411 2 17 33
Trial 49: 17445 1 16 33
Trial 50: 17478 1 16 33
Trial 51: 17511 2 17 34
Trial 52: 17545 1 16 33
Trial 53: 17578 2 17 33
Trial 54: 17611 2 17 34
Trial 55: 17645 1 16 33
Trial 56: 17678 1 16 33
Trial 57: 17711 2 17 33
Trial 58: 17745 1 16 33
Trial 59: 17778 1 16 33
Trial 60: 17812 1 16 32
Trial 61: 17845 1 16 33
Trial 62: 17878 1 16 33
Trial 63: 17911 2 17 33
Trial 64: 17944 2 17 34
Trial 65: 17978 1 16 33
Trial 66: 18011 2 17 33
Trial 67: 18044 2 17 34
Trial 68: 18078 1 16 33
Trial 69: 18111 1 17 33
Trial 70: 18144 2 17 34
Trial 71: 18178 1 16 33
Trial 72: 18211 1 17 33
Trial 73: 18244 2 17 34
Trial 74: 18278 1 16 33
Trial 75: 18311 2 17 33
Trial 76: 18344 2 17 34
Trial 77: 18378 1 16 33
Trial 78: 18411 2 17 33
Trial 79: 18444 2 17 34
Trial 80: 18478 1 16 33
Trial 81: 18511 2 17 33
Trial 82: 18544 2 17 34
Trial 83: 18578 1 16 33
Trial 84: 18611 2 17 33
Trial 85: 18644 2 17 34
Trial 86: 18678 1 16 33
Trial 87: 18711 1 17 33
Trial 88: 18744 2 17 34
Trial 89: 18778 1 16 33
Trial 90: 18811 1 17 33
Trial 91: 18844 2 17 34
Trial 92: 18878 1 16 33
Trial 93: 18911 1 17 33
Trial 94: 18944 2 17 34
Trial 95: 18978 1 16 33
Trial 96: 19011 1 17 33
Trial 97: 19044 2 17 34
Trial 98: 19078 1 16 33
Trial 99: 19111 2 17 33
Trial 100: 19144 2 17 33
Debug printing took 214
*****WAIT AFTER CNVSCOPY****
Trial 1: 19393 2 18 18
Trial 2: 19411 1 16 17
Trial 3: 19428 1 16 16
Trial 4: 19445 1 16 16
Trial 5: 19461 1 16 17
Trial 6: 19478 1 16 16
Trial 7: 19495 1 16 16
Trial 8: 19511 2 17 17
Trial 9: 19528 2 16 16
Trial 10: 19544 2 17 17
Trial 11: 19561 1 16 17
Trial 12: 19578 1 16 16
Trial 13: 19594 2 17 17
Trial 14: 19611 1 16 17
Trial 15: 19628 1 16 16
Trial 16: 19644 2 17 17
Trial 17: 19661 1 16 17
Trial 18: 19678 1 16 16
Trial 19: 19694 2 17 17
Trial 20: 19711 1 16 17
Trial 21: 19728 1 16 16
Trial 22: 19744 2 17 17
Trial 23: 19761 2 16 17
Trial 24: 19778 1 16 16
Trial 25: 19794 2 17 17
Trial 26: 19811 1 16 17
Trial 27: 19828 1 16 16
Trial 28: 19844 2 17 17
Trial 29: 19861 1 16 17
Trial 30: 19878 1 16 16
Trial 31: 19894 2 17 17
Trial 32: 19911 1 16 17
Trial 33: 19928 1 16 16
Trial 34: 19944 2 17 17
Trial 35: 19961 1 16 16
Trial 36: 19978 1 16 16
Trial 37: 19994 2 17 17
Trial 38: 20011 1 16 17
Trial 39: 20028 1 16 16
Trial 40: 20044 2 17 17
Trial 41: 20061 1 16 17
Trial 42: 20078 1 16 16
Trial 43: 20094 2 17 17
Trial 44: 20111 1 16 16
Trial 45: 20128 1 16 16
Trial 46: 20144 2 17 17
Trial 47: 20161 1 16 16
Trial 48: 20178 1 16 16
Trial 49: 20194 2 17 17
Trial 50: 20211 1 16 17
Trial 51: 20228 1 16 16
Trial 52: 20244 2 17 17
Trial 53: 20261 1 16 17
Trial 54: 20278 1 16 16
Trial 55: 20294 1 17 17
Trial 56: 20311 1 16 16
Trial 57: 20328 1 16 16
Trial 58: 20344 2 17 17
Trial 59: 20361 1 16 16
Trial 60: 20377 2 17 17
Trial 61: 20394 2 17 17
Trial 62: 20411 1 16 16
Trial 63: 20427 2 17 17
Trial 64: 20444 2 17 17
Trial 65: 20461 1 16 16
Trial 66: 20478 1 16 16
Trial 67: 20494 2 17 17
Trial 68: 20511 1 16 16
Trial 69: 20528 1 16 16
Trial 70: 20544 1 17 17
Trial 71: 20561 1 16 16
Trial 72: 20577 2 17 17
Trial 73: 20594 2 17 17
Trial 74: 20611 1 16 16
Trial 75: 20627 2 17 17
Trial 76: 20644 1 17 17
Trial 77: 20661 1 16 16
Trial 78: 20677 2 17 17
Trial 79: 20694 1 17 17
Trial 80: 20711 1 16 16
Trial 81: 20728 1 16 16
Trial 82: 20744 2 17 17
Trial 83: 20761 1 16 16
Trial 84: 20778 1 16 16
Trial 85: 20794 2 17 17
Trial 86: 20811 1 16 16
Trial 87: 20828 1 16 16
Trial 88: 20844 2 17 17
Trial 89: 20861 1 16 16
Trial 90: 20877 2 17 17
Trial 91: 20894 1 17 17
Trial 92: 20911 1 16 16
Trial 93: 20928 1 16 16
Trial 94: 20944 1 17 17
Trial 95: 20961 1 16 16
Trial 96: 20977 2 17 17
Trial 97: 20994 2 17 17
Trial 98: 21011 1 16 16
Trial 99: 21027 2 17 17
Trial 100: 21044 1 16 17

----
Clearly then, something strange is going on. If anyone would like to verify
this on their own PC/E-Prime, be my guest.
Best,
Michiel

-----Original Message-----
From: e-prime at googlegroups.com [mailto:e-prime at googlegroups.com] On Behalf
Of David McFarlane
Sent: 25. April 2013 18:16
To: e-prime at googlegroups.com; e-prime at googlegroups.com
Subject: Re: Canvas.Copy is taking too long to complete

Tamar,

Very curious indeed, I wish I had the time to explore this further myself.
You should definitely take this now to PST Web Support at
http://support.pstnet.com/e%2Dprime/support/login.asp
, and send them a link to this discussion (for your convenience, that link
is https://groups.google.com/d/topic/e-prime/OX528cBioek
).  And then please post back with the results.

Thanks,
-----
David McFarlane
E-Prime training
online:  http://psychology.msu.edu/Workshops_Courses/eprime.aspx
Twitter:  @EPrimeMaster (https://twitter.com/EPrimeMaster)

At 4/25/2013 03:24 AM Thursday, Peter Quain wrote:

>there must be some interfacing routines we can't 
>see in the *.ebs files that differ between v1.? 
>and v.2.?, and that e-prime calls when the 
>scripts are run??? They both(?) must be 
>allowable, and they must call upon different 
>routines in e-prime that communicate with the hardware?
>
>At 05:08 PM 25/04/2013, you wrote:
>>o.k., here is what I found, following your input:
>>
>>In any experiment I create in EP1 (in a 
>>neighboring lab...), canvas.copy takes under 1 ms.
>>In any experiment I create in EP2, canvas.copy takes a whole refresh
cycle.
>>If I take an experiment created in EP1 and 
>>convert it to EP2 - then canvas.copy time is 
>>under 1 ms... although nothing in the inline changed...
>>How can that be?
>>
>>
>>
>>On Thursday, April 25, 2013 8:29:06 AM UTC+3, Peter Quain wrote:
>>I haven't tested any code examples, but have a 
>>lot of data showing canvas.copy in v.1.?.? 
>>takes under a ms, supporting David's 
>>observations. Perhaps something here is less 
>>instant in v2.?, and a bug has been identified?
>>At 03:19 PM 25/04/2013, you wrote:
>>>Thank you both your replies!
>>>I am using E-prime 2.0.10, and a CRT iiyama 
>>>Vision Master screen, with display resolution
>>>of 1024 x 768 and a refresh rate of 100 Hz. My 
>>>operating system is windows XP.
>>>I'm troubled with this timing issue because my 
>>>experiment includes EEG recording, thus the
>>>synchronization is terribly important. I need 
>>>to send triggers via the parallel port exactly at the
>>>onset of each stimulus, or else my EEG signal 
>>>might be smeared. Considering that the canvas.copy
>>>takes a refresh cycle to complete - I'm not 
>>>sure what time ought to be considered the stimulus onset...
>>>Anyhow, David, I've tried running your code - 
>>>and I get dt's of 13-14ms. Do you think that all the difference
>>>between your 0.22ms to my 13-14ms is due to 
>>>E-prime1 vs. E-prime2 differences? That's shocking...
>>>I get the same results as Michiel for the loop 
>>>codes, as puzzling as they are...
>>>Thanks again for your help,
>>>Tamar
>>>
>>>
>>>
>>>On Wednesday, April 24, 2013 4:44:46 PM UTC+3, McFarlane, David wrote:
>>>Hmm.  I explored this issue myself three years ago, using EP1 (still my
>>>favorite version for this type of exploration).  I just dug up my test
>>>program and ran it again on my trusty old XP laptop at home after
>>>breakfast, and got times of 0.22 ms even for full screen copies, much as
>>>I remember from before (where full screen means 1024 x 768; and yes,
>>>that is less than a millisecond).  To be sure, here is the core of my
>>>test code:
>>>      t0 = clock.readmicrosec
>>>      dcnvs.copy cnvs
>>>      dt = clock.readmicrosec - t0
>>>      msgbox format$( dt/1000, "Standard" ) & " ms"
>>>where all variables are defined and initialized earlier as expected
>>>(dcnvs is set to Display.Canvas just for notational convenience).
>>>Also, I looked at the Canvas.Copy topic in the E-Basic Help -- no
>>>evidence that .Copy includes an implicit Display.WaitForVerticalBlank,
>>>to the contrary, the code example there includes an explicit
>>>Display.WaitForVerticalBlank just before the cnvs.Copy.  I would be
>>>*extremely* surprised if Canvas.Copy included a
>>>Display.WaitForVerticalBlank, as that would greatly compromise its
>>>utility (e.g., when wanting to Copy several segments to an offscreen
>>>Canvas before copying the complete result to Display.Canvas).
>>>So I do not know how to account for your results.  Mind you, I did all
>>>my tests using good-old EP1 with 1024x768 display resolution.  For all I
>>>know things changed with the latest EP version, or things get slower
>>>with larger display resolutions.  What EP version do you use?  What
>>>display resolution?
>>>Michiel, I am especially puzzled by your results.  Both of your tests
>>>measure the total time to perform a Canvas.Copy and
>>>Display.WaitForVerticalBlank, only in different orders.  So you should
>>>get the same time for both tests, regardless of whether Canvas.Copy
>>>includes its own Display.WaitForVerticalBlank.  What am I missing?
>>>Nevertheless, Michiel's advice still stands  -- as long as your program
>>>does everything it needs to do within one screen refresh (and assuming
>>>that you *do* synchronize visual displays to the screen refresh, as you
>>>should), then that is good enough.
>>>-----
>>>David McFarlane
>>>E-Prime training online:
>>><http://psychology.msu.edu/Workshops_Courses/eprime.aspx>http://psycholog
y.msu.edu/Workshops_Courses/eprime.aspx 
>>>
>>>Twitter:  @EPrimeMaster 
>>>(<http://twitter.com/EPrimeMaster>twitter.com/EPrimeMaster)
>>>/-----------
>>>Stock reminder:  1) I do not work for PST.  2) PST's trained staff take
>>>any and all questions at
>>><http://support.pstnet.com/e%2Dprime/support/login.asp>http://support.pst
net.com/e%2Dprime/support/login.asp 
>>>, and they strive
>>>to respond to all requests in 24-48 hours, so make full use of it.  3)
>>>In addition, PST takes questions at their Facebook page
>>>(
http://www.facebook.com/pages/Psychology-Software-Tools-Inc/241802160683
>>>), and offers several instructional videos there and on their YouTube
>>>channel ( http://www.youtube.com/user/PSTNET ) (no Twitter feed yet,
>>>though).  4) If you do get an answer from PST staff, please extend the
>>>courtesy of posting their reply back here for the sake of others.
>>>\-----------
>>>Cognitology wrote:
>>> > Hi,
>>> >
>>> > A quick look, but I think that you pretty much nailed it: it can take
>>> > quite long to do any canvas operation. Given that your screen refresh
>>> > rate presumably isnï¿½t more than 100 Hz (and in any ways, your foveal
>>> > vision isnï¿½t), I donï¿½t see the problem? 
>>> Indeed, if you were to draw many
>>> > things to the main canvas, one after the other, then indeed, it gets
to
>>> > be a problem, but as long as the only 
>>> operation is copying a ï¿½preloadedï¿½
>>> > canvas to the shown one, it doesnï¿½t 
>>> matter all that much. Notice, given
>>> > that youï¿½re not using E-Primeï¿½s 
>>> stimdisplays, itï¿½s not clear at what
>>> > time the stimulus is actually displayed ï¿½ 
>>> only when itï¿½s done sending
>>> > the command. I think itï¿½s generally better for critical timing
aspects
>>> > of your experiment to avoid canvas as much as possible. Personally, I
>>> > think ï¿½critical timingï¿½ is when it concerns a subliminal vs barely
>>> > supraliminal prime or some such, for other types of stimuli the 10 ms
of
>>> > (constant, therefore presumably stimulus independent) delay is of
>>> > trivial concern.
>>> >
>>> >
>>> >
>>> > Just testing some of it myself, and I get values ranging between 15
and
>>> > 17 ï¿½ which is funny, given that my refresh rate is indeed 60, so it
>>> > seems a bit like thereï¿½s some sort of 
>>> display.waitforverticalblank built
>>> > into canvas.copy. Curiously, this:
>>> >
>>> > For j = 1 To 100
>>> >
>>> >       DrawFixation ï¿½this is just a custom function drawing a line to
>>> > cnvsnext
>>> >
>>> >       cnvs.copy cnvsnext
>>> >
>>> >       display.waitforverticalblank
>>> >
>>> >       debug.print clock.read - clocktime
>>> >
>>> >       clocktime = clock.read
>>> >
>>> > Next j
>>> >
>>> >
>>> >
>>> > Gives me latencies equal to refresh rates (+- 1 ms).
>>> >
>>> > Whereas:
>>> >
>>> >
>>> >
>>> > For j = 1 To 100
>>> >
>>> >       DrawFixation ï¿½this is just a custom function drawing a line to
>>> > cnvsnext
>>> >
>>> >       display.waitforverticalblank
>>> >
>>> > cnvs.copy cnvsnext
>>> >
>>> >       debug.print clock.read - clocktime
>>> >
>>> >       clocktime = clock.read
>>> >
>>> > Next j
>>> >
>>> >
>>> >
>>> > Gives me latencies equal to 2xrefresh rates. Somebody with young eyes
>>> > should tell us if the first one doesnï¿½t have cutting-off errors,
>>> > otherwise Iï¿½d suggest there might be some sort of
waitforverticalblank
>>> > built into canvas.copy.
>>> >
>>> > Best,
>>> >
>>> >
>>> >
>>> > Michiel Sovijï¿½rvi-Spapï¿½
>>> >
>>> >
>>> >
>>> > Helsinki Institute for Information Technology
>>> >
>>> > Aalto & University of Helsinki
>>> >
>>> > Finland
>>> >
>>> >
>>> >
>>> >
>>> >
>>> >
>>> >
>>> > BTW: notice that using debug.print also incurs a delay (last measured
at
>>> > 0.7 ms).
>>> >
>>> >
>>> >
>>> >
>>> >
>>> > *From:* e-p... at googlegroups.com [ mailto:e-p... at googlegroups.com] *On
>>> > Behalf Of *Tamar
>>> > *Sent:* 24. April 2013 08:33
>>> > *To:* e-p... at googlegroups.com
>>> > *Subject:* Canvas.Copy is taking too long to complete
>>> >
>>> >
>>> >
>>> > I'm programming a visual experiment, and suffering from some timing
>>> > issues. It seems that the line presenting the stimuli (canvas.copy) is
>>> > considerably time consuming: 10-12 ms. I can't figure out the cause
for
>>> > this delay, and I would appreciate any help...
>>> >
>>> > Here is the relevant piece of code:
>>> >
>>> > ====== in an initializing inline script, at the begining of
SessionProc:
>>> > ======
>>> > Set MainCanvas = Display.Canvas
>>> > MainCanvas.fillColor = CColor(background_color)
>>> > MainCanvas.clear
>>> >
>>> > For i = 1 To NumStim
>>> >    Set StimCanvases(i) = Display.CreateCanvas
>>> >
>>> >    'define destination rect as center of screen
>>> >    destRects(i).Left = Display.XRes/2-stim_w/2
>>> >    destRects(i).Top = Display.YRes/2-stim_h/2
>>> >    destRects(i).Right = Display.XRes/2+stim_w/2
>>> >    destRects(i).Bottom = Display.YRes/2+stim_h/2
>>> >
>>> >    'define source rect as upper left corner
>>> >    srcRects(i).Left = 0
>>> >    srcRects(i).Top = 0
>>> >    srcRects(i).Right = stim_w
>>> >    srcRects(i).Bottom = stim_h
>>> >
>>> >    'Load the image file
>>> >    StimCanvases(i).LoadImage "Stimuli/" & FileNames(i) & ".bmp"
>>> >
>>> > Next i
>>> >
>>> > ====== in the inline of TrialProc: =======
>>> > Debug.Print "1:" & clock.read
>>> > StartTrialTime = clock.read
>>> > n = c.GetAttrib("CanvasNum")
>>> > c.SetAttrib "TrialStart", StartTrialTime
>>> > display.WaitForVerticalBlank
>>> > Debug.Print "4:" & clock.read
>>> > StartStimTime = clock.read
>>> > c.SetAttrib "StimStart", StartStimTime
>>> > Debug.Print "5:" & clock.read
>>> > mainCanvas.copy StimCanvases(n),srcRects(n),destRects(n)
>>> > Debug.Print "6:" & clock.read
>>> >
>>> >
>>> > I've tried a few things:
>>> > - to create variables taking the values of
>>> > StimCanvases(n),srcRects(n),destRects(n) in the beginning of the
trial,
>>> > so the mainCanvas.copy line would not need to approach the arrays.
>>> > - to present other simple canvases instead of my real stimuli (just a
>>> > fixation, for example. or an empty canvas)
>>> > - to draw something on the mainCanvas rather than copy a new canvas to
>>> > it (e.g. mainCanvas.Circle).
>>> >
>>> > All of these takes 10-12 ms! (as calculated by subtracting time5 from
>>> > time6). The only way I managed to get rid of the delay was to erase
the
>>> > entire row...
>>> >
>>> > Am I missing something here?...
>>> >
>>> > Thanks,
>>> > Tamar

-- 
You received this message because you are subscribed to the Google Groups
"E-Prime" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to e-prime+unsubscribe at googlegroups.com.
To post to this group, send email to e-prime at googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

-- 
You received this message because you are subscribed to the Google Groups "E-Prime" group.
To unsubscribe from this group and stop receiving emails from it, send an email to e-prime+unsubscribe at googlegroups.com.
To post to this group, send email to e-prime at googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.