/usr/share/psychtoolbox-3/PsychTests/AnalyzeTiming.m is in psychtoolbox-3-common 3.0.11.20131230.dfsg1-1build1.
This file is owned by root:root, with mode 0o644.
The actual contents of the file can be viewed below.
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 | function AnalyzeTiming(fname)
global valids;
global res;
global deltas;
global vdeltas;
global vrawdeltas;
global skippedones;
% Load result file: Will create struct 'res' with data:
load(fname);
disp(res);
if ~isempty(findstr(res.OSName, 'OSX'))
res.failFlag(res.measuredTime > 1e6) = -1;
res.measuredTime(res.measuredTime > 1e6) = nan;
end
% Discard 1st frame by marking it as invalid:
res.failFlag(1) = -1;
valids = find(res.failFlag == 0);
%skippedones = find(abs(res.onsetFlipTime - res.predictedOnset) > 0.9 * res.ifi);
skippedones = find(abs(res.measuredTime - res.predictedOnset) > 0.75 * res.ifi);
skippedones = intersect(skippedones, valids);
fprintf('\n\n\n');
fprintf('Comments: %s\n', res.Comments);
fprintf('Number of skipped frames: %i\n', length(skippedones));
fprintf('Number of corrupted frames: %i\n', length(find(res.failFlag > 0)));
deltas = res.measuredTime - res.onsetFlipTime;
fprintf('Number of > 1.6 msecs disagreement meas vs. flip: %i\n', length(find(abs(deltas(valids)) > 0.0016)));
fprintf('Number of flip >= 0.66 ifi later than meas. (Excessive wakeup-delay): %i\n', length(find(deltas(valids) < -0.66 * res.ifi)));
% Only take deltas of valid frames into account:
vdeltas = 1000 * deltas(valids); %#ok<FNDSB>
fprintf('Valid high-precision frames: Mean difference %f msecs, stddev %f msecs, range %f msecs.\n', mean(vdeltas), std(vdeltas), range(vdeltas));
vrawdeltas = 1000 * (res.measuredTime(valids) - res.rawFlipTime(valids));
fprintf('Valid raw-precision frames: Mean difference %f msecs, stddev %f msecs, range %f msecs.\n', mean(vrawdeltas), std(vrawdeltas), range(vrawdeltas));
fprintf('Scheduling / wakeup delay vbl onset (swap) to wakeup: Mean %f msecs, Max %f msecs.\n', 1000 * mean(res.rawFlipTime(valids) - res.vblFlipTime(valids)), 1000 * max(res.rawFlipTime(valids) - res.vblFlipTime(valids)));
if isfield(res, 'swapRequestSubmissionTime')
fprintf('Headroom for swaprequest submission, predictedonset - swapreqtime: Mean %f msecs, Max %f msecs.\n', 1000 * mean(res.predictedOnset(valids) - res.swapRequestSubmissionTime(valids)), 1000 * max(res.predictedOnset(valids) - res.swapRequestSubmissionTime(valids)));
end
for i=1:10
if ~isempty(find(res.waitFramesSched(valids) == i))
skipcount(i) = length(find(res.waitFramesSched(skippedones) == i));
skipratio(i) = skipcount(i) / length(find(res.waitFramesSched(valids) == i));
else
skipcount(i) = nan;
skipratio(i) = nan;
end
end
if length(skippedones) < 25
skippedOnes = skippedones
end
fprintf('\n');
fprintf('Skipcount for 2 frames sched: %i, Skipcount for > 2 frame: %i, Ratio: %f %%\n', skipcount(2), length(skippedones) - skipcount(2), 100 * skipcount(2) / length(skippedones));
if length(res.waitFramesSched) > 2*4972
firstHalfSkips = length(find(skippedones <= 4972));
secondHalfSkips = length(find(skippedones > 4972));
fprintf('Skipped during regular intervals (1st half): %i\n', firstHalfSkips);
fprintf('Skipped during randomized intervals (2nd half): %i\n', secondHalfSkips);
end
close all;
figure;
plot(skipratio);
title('Ratio of skipped frames vs. total frames per waitFramesSched:');
figure;
plot(skipcount);
title('Number of skipped frames per waitFramesSched:');
if isfield(res, 'TimeAtSwapBuffers')
waitedswap = intersect(skippedones, find((res.swapRequestSubmissionTime - res.targetWhentime) < 0));
%waitedswap = 1:9953;
if ~isempty(waitedswap)
figure ; plot(1000 * (res.TimeAtSwapBuffers(waitedswap) - res.targetWhentime(waitedswap)));
title('Wakeup delay from timed wait (scheduling delay) before SwapBuffers() call: [msecs]:');
end
if ~isempty(skippedones)
figure ; plot(1000 * (res.swapRequestSubmissionTime(skippedones) - res.targetWhentime(skippedones)));
title('Invocation time of Screen(''Flip'') relative to when deadline (positive == delayed): [msecs]:');
figure ; plot(1000 * (res.targetWhentime(skippedones) + 0.5 * res.ifi - res.TimeAtSwapBuffers(skippedones)));
title('Headroom between VSYNC deadline and time of SwapBuffers (positive = good): [msecs]:');
figure; scatter(skippedones,repmat(1,1,length(skippedones)))
title('Placement of skipped frames: x-position == frameId');
%figure ; plot(diff(res.targetWhentime(skippedones) + 0.5 * res.ifi));
%title('VSYNC deadline of skipped frames: [secs]:');
end
end
% Plot distribution of raw flip timestamps wrt. high-precision timestamps:
figure;
hist(1000 * (res.rawFlipTime(2:end) - res.vblFlipTime(2:end)), 100)
title('Histogram: Delay of rawtimestamp wrt. real vbltime of bufferswap');
xlabel('Delay [msecs]');
ylabel('Count');
return;
|