This file is indexed.

/usr/share/psychtoolbox-3/PsychTests/AnalyzeTiming.m is in psychtoolbox-3-common 3.0.11.20140816.dfsg1-1.

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;