seandr:A posttrialpause gives Inquisit a fixed time buffer after the trial to erase stimuli and do some other minor cleanup. With a posttrialpause defined, you shouldn't see any delay from erasing stimuli. Without the posttrialpause, I would expect to see some small delays.
Sorry to keep dragging this on, but I'd like to point out that all stims in the testscript are set to '/erase=false', i.e. Inquisit shouldn't have to erase anything ever. The only thing remaining is the "other minor cleanup" (resetting trial properties and such, I assume). And yet -- with posttrialpause=0 -- approx. 2 additional frames are added to each trial. Granted, I'd also expect some (very) small delays for the minor cleanup, but I don't see why this should take 2 frames (~34 ms) because there is no screen / display erasing involved whatsoever. Considering the sheer number of processor and memory operations modern PCs can perform within microseconds, I'd expect the minor cleanup to be virtually undetectable. I definitely don't understand why it adds 2 frames (even one frame would be too much, IMO). Any input is greatly appreciated!
~Dave
P.S.: As mentioned previously, I think there may be a bug involving the 'stimulusonset' property: 'shape.myshape.stimulusonset.1' always returns an empty value on my system (Inquisit 3.0.5.0), despite the stimulus having been displayed and thus having an onset to report.
"To understand recursion, you must first understand recursion." - Unknown Zen Master
I've tested the script with /postrialpause=0 and am seeing intermittent delays between 30-34 ms.
Any resemblance these numbers have to the refresh rate is purely coincidental given that there is no stimulus erasure happening with your test script. At the end of the trial, Inquisit does a few things, including:
1) Captures the screen and saves it to disk (if applicable)2) Erase stimuli and show feedback stimuli (if applicable)3) Update stats for the expt, block, and trial4) Evaluates any /ontrialend expressions5) Writes trial data to the file6) Erases any feedback stimuli (if applicable)7) Releases any video memory used by shapes or pictures (if applicable)8) Clear any pending input messages from the relevant response buffer
The only item in this list that could possibly require 30ms is 5 - writing the data to disk. Sure enough, when I removed the /audit command from the <data> element and replaced it with /separatefiles=true (which causes Inquisit to save the data in memory and then write it all at once to disk at the end of the experiment), the 30ms delay goes away. I'd love to know if you see the same thing.
Anyway, I think we have our culprit - disk access.
-Sean
Hi Sean,
many thanks for giving this another look and your detailed response. Here are my observations as requested:
(1) / audit = true had nothing to do with my initial observation. In fact I never even ran the script with auditing turned on.
(2) / separatefiles = true doesn't resolve the issue for me. In fact it makes the delay even worse (~45ms mean).
Thanks again,
P.S.: Can you replicate the empty stimulusonset property issue?
A couple of more observations from tests conducted today:
- Even setting recorddata=false to prevent disc access does not resolve the issue for me. While the delay is somewhat reduced, there are still approx. 33ms added to each trial.
- Unrelated to the timing issue: recorddata doesn't seem to work when set at the <expt> level.
Weird. I've run the test several more times with both data recording and auditing turned on, and I'm seeing trial durations all in the range of 1000-1001 ms. I've run the test on a fast and slow machine with the same results. I can't even reproduce the delays I initially saw, and I'm actually thinking those resulted from me running the tests using a debug build with the debugger attached.
Just to make sure we are looking at the same numbers, I'm looking at the "Difference" value as a measure of the trial duration - is that what you are looking at?
P.S. If you are still seeing the delays, it would be interesting to know whether any of the following steps cumulatively have an impact:
1) Removing all data and audit recording (you've already done this)2) Remove the ontrialend logic and the text stimuli showing the debug info from the3) Remove the shape stimuli from the presentation
Thanks for the reply, Sean. Really weird. I can reproduce these delays reliably, though.
seandr:Just to make sure we are looking at the same numbers, I'm looking at the "Difference" value as a measure of the trial duration - is that what you are looking at?
Yes, that's what I'm talking about. The mean difference to be precise. In the test script, "Difference" reflects the duration of the last trial (measured as difference between the previous and current trial's start time), "Mean" reflects the mean duration across all trials.
Thanks,
Ah, that might explain the discrepancy. The mean difference includes "start_trial", which does not have a fixed length (it's length depends on how quickly you respond). The performance in question is the duration of the fixed length trials, so the mean difference isn't relevant.
I've been opening the data file and looking at the reported difference for each fixed length trial, and all the durations have fallen within the range of 1000-1001. Are you seeing any single trial durations outside this range?
seandr:Ah, that might explain the discrepancy. The mean difference includes "start_trial", which does not have a fixed length (it's length depends on how quickly you respond). The performance in question is the duration of the fixed length trials, so the mean difference isn't relevant.
No. My script corrects for that.
More weird - did you update the test script? I just downloaded it again, and the calculations were different than the script I previous had. The version I have now does indeed correct for the start_trial.
I'm still not seeing any delays larger than 1ms, however. I'll try on some more machines...
seandr:More weird - did you update the test script? I just downloaded it again, and the calculations were different than the script I previous had. The version I have now does indeed correct for the start_trial.
I might have initially uploaded the wrong version -- however said version can't have been online for more than a couple of minutes... Sorry for the confusion.
Dear Dave/Sean,
Many thanks once again for the extensive testing and many helpful comments you guys have provided on this topic - really, really helpful. I'm very happy to report that including a post-trial pause, setting erase=false for all my stimuli, and updating to the latest build of Inquisit have pretty much solved the problem I was having - Dave's debugging timing code reports trial durations which are pretty much bang-on, with an occasional deviation by a millisecond or two. Testing with external hardware (getting Inquisit to output a TTL pulse on the parallel port with each trial and recording it with a analogue-digital converter with 1ms resolution) confirms that the timing is accurate as well. This is a massive improvement over the situation I was in before and I'm re-commencing my experiments with renewed confidence in what I'm doing.
Interestingly, the above is only true on the computer I use for testing - when I run the programs on the computer in my office (similar specifications) I still see timing lags. Nevertheless, at least with Dave's debugging code I can be certain about what's going on whatever hardware I use in the future.
I have a suggestion actually - it would have been immensely helpful to me if the timing code had been easily available somewhere. I've been using Inquisit for a while but am in no way a 'proper' programmer and had no idea Inquisit could be used in this way, and even less idea how to implement those functions. Would it perhaps be possible to include an example script similar to Dave's in the Inquisit Task Library on the main website?
Many, many thanks again,
Matt.
matt2004:Interestingly, the above is only true on the computer I use for testing - when I run the programs on the computer in my office (similar specifications) I still see timing lags.
Request for clarification, if I may: This is to say that on your office PC
(a) the debugging script does not report timing lags although there are such lags (as measured via external equipment / TTL)?
or
(b) the debugging script does accurately report timing lags despite the various optimizations (postrialpause, erase=false, etc)?
Dave,
Sorry for being unclear - what I meant was b), i.e. the debugging script is showing lags of about 30ms on each trial, despite all the optimisations.
Cheers,
M.
Ok, I've dug more deeply into this, and identified the cause of the extra lags. Basically, the lags are equal to two retrace intervals of the monitors (as Dave had earlier surmised).
The first interval is because when Inquisit prepares to write the stimuli to the screen, it stalls until the beginning of a retrace interval. This can take up to 1 interval in duration and is currently added to the total duration of the trial, assuming no postrialpause is set.
The 2nd interval lag was simply a bug as Inquisit mistakenly waited until the next interval began before advancing.
Both of these lags were consumed into the posttrialpause, so they wouldn't affect timing if that command is set. I will hopefully have a fix ready for both shortly.