Home | History | Annotate | Download | only in test 
      1 function [t, TS] = plotReceiveTrace(filename, flat)
      2 fid=fopen(filename);
      3 %DEBUG     ; ( 8:32:33:375 |    0)        VIDEO:1          ;      5260; First packet of frame 1869537938
      4 %DEBUG     ; ( 8:32:33:375 |    0) VIDEO CODING:1          ;      5260; Decoding timestamp 1869534934
      5 %DEBUG     ; ( 8:32:33:375 |    0)        VIDEO:1          ;      5260; Render frame 1869534934 at 20772610
      6 %DEBUG     ; ( 8:32:33:375 |    0) VIDEO CODING:-1         ;      5260; Frame decoded: timeStamp=1870511259 decTime=0 maxDecTime=0, at 19965
      7 %DEBUG     ; ( 7:59:42:500 |    0)        VIDEO:-1         ;      2500; Received complete frame timestamp 1870514263 frame type 1 frame size 7862 at time 19965, jitter estimate was 130
      8 %DEBUG     ; ( 8: 5:51:774 |    0)        VIDEO:-1         ;      3968; ExtrapolateLocalTime(1870967878)=24971 ms
      9 
     10 if nargin == 1
     11     flat = 0;
     12 end
     13 line = fgetl(fid);
     14 estimatedArrivalTime = [];
     15 packetTime = [];
     16 firstPacketTime = [];
     17 decodeTime = [];
     18 decodeCompleteTime = [];
     19 renderTime = [];
     20 completeTime = [];
     21 while ischar(line)%line ~= -1
     22     if length(line) == 0
     23         line = fgetl(fid);
     24         continue;
     25     end
     26     % Parse the trace line header
     27     [tempres, count] = sscanf(line, 'DEBUG     ; (%u:%u:%u:%u |%*lu)%13c:');
     28     if count < 5
     29         line = fgetl(fid);
     30         continue;
     31     end
     32     hr=tempres(1);
     33     mn=tempres(2);
     34     sec=tempres(3);
     35     ms=tempres(4);
     36     timeInMs=hr*60*60*1000 + mn*60*1000 + sec*1000 + ms;
     37     label = tempres(5:end);
     38     I = find(label ~= 32); 
     39     label = label(I(1):end); % remove white spaces
     40     if ~strncmp(char(label), 'VIDEO', 5) & ~strncmp(char(label), 'VIDEO CODING', 12)
     41         line = fgetl(fid);
     42         continue;
     43     end
     44     message = line(72:end);
     45     
     46     % Parse message
     47     [p, count] = sscanf(message, 'ExtrapolateLocalTime(%lu)=%lu ms');
     48     if count == 2
     49         estimatedArrivalTime = [estimatedArrivalTime; p'];
     50         line = fgetl(fid);
     51         continue;
     52     end
     53     
     54     [p, count] = sscanf(message, 'Packet seqNo %u of frame %lu at %lu');
     55     if count == 3
     56         packetTime = [packetTime; p'];
     57         line = fgetl(fid);
     58         continue;
     59     end
     60     
     61     [p, count] = sscanf(message, 'First packet of frame %lu at %lu');
     62     if count == 2
     63         firstPacketTime = [firstPacketTime; p'];
     64         line = fgetl(fid);
     65         continue;
     66     end
     67     
     68     [p, count] = sscanf(message, 'Decoding timestamp %lu at %lu');
     69     if count == 2
     70         decodeTime = [decodeTime; p'];
     71         line = fgetl(fid);
     72         continue;        
     73     end
     74     
     75     [p, count] = sscanf(message, 'Render frame %lu at %lu. Render delay %lu, required delay %lu, max decode time %lu, min total delay %lu');
     76     if count == 6
     77         renderTime = [renderTime; p'];
     78         line = fgetl(fid);
     79         continue;
     80     end
     81 
     82     [p, count] = sscanf(message, 'Frame decoded: timeStamp=%lu decTime=%d maxDecTime=%lu, at %lu');
     83     if count == 4
     84         decodeCompleteTime = [decodeCompleteTime; p'];
     85         line = fgetl(fid);
     86         continue;
     87     end
     88 
     89     [p, count] = sscanf(message, 'Received complete frame timestamp %lu frame type %u frame size %*u at time %lu, jitter estimate was %lu');
     90     if count == 4
     91         completeTime = [completeTime; p'];
     92         line = fgetl(fid);
     93         continue;
     94     end
     95     
     96     line = fgetl(fid);
     97 end
     98 fclose(fid);
     99 
    100 t = completeTime(:,3);
    101 TS = completeTime(:,1);
    102 
    103 figure;
    104 subplot(211);
    105 hold on;
    106 slope = 0;
    107 
    108 if sum(size(packetTime)) > 0
    109     % Plot the time when each packet arrives
    110     firstTimeStamp = packetTime(1,2);
    111     x = (packetTime(:,2) - firstTimeStamp)/90;
    112     if flat
    113         slope = x;
    114     end
    115     firstTime = packetTime(1,3);
    116     plot(x, packetTime(:,3) - firstTime - slope, 'b.');
    117 else
    118     % Plot the time when the first packet of a frame arrives
    119     firstTimeStamp = firstPacketTime(1,1);
    120     x = (firstPacketTime(:,1) - firstTimeStamp)/90;
    121     if flat
    122         slope = x;
    123     end
    124     firstTime = firstPacketTime(1,2);
    125     plot(x, firstPacketTime(:,2) - firstTime - slope, 'b.');
    126 end
    127 
    128 % Plot the frame complete time
    129 if prod(size(completeTime)) > 0
    130     x = (completeTime(:,1) - firstTimeStamp)/90;
    131     if flat
    132         slope = x;
    133     end
    134     plot(x, completeTime(:,3) - firstTime - slope, 'ks');
    135 end
    136 
    137 % Plot the time the decode starts
    138 if prod(size(decodeTime)) > 0
    139     x = (decodeTime(:,1) - firstTimeStamp)/90;
    140     if flat
    141         slope = x;
    142     end
    143     plot(x, decodeTime(:,2) - firstTime - slope, 'r.');
    144 end
    145 
    146 % Plot the decode complete time
    147 if prod(size(decodeCompleteTime)) > 0
    148     x = (decodeCompleteTime(:,1) - firstTimeStamp)/90;
    149     if flat
    150         slope = x;
    151     end
    152     plot(x, decodeCompleteTime(:,4) - firstTime - slope, 'g.');
    153 end
    154 
    155 if prod(size(renderTime)) > 0
    156     % Plot the wanted render time in ms
    157     x = (renderTime(:,1) - firstTimeStamp)/90;
    158     if flat
    159         slope = x;
    160     end
    161     plot(x, renderTime(:,2) - firstTime - slope, 'c-');
    162     
    163     % Plot the render time if there were no render delay or decoding delay.
    164     x = (renderTime(:,1) - firstTimeStamp)/90;
    165     if flat
    166         slope = x;
    167     end
    168     plot(x, renderTime(:,2) - firstTime - slope - renderTime(:, 3) - renderTime(:, 5), 'c--');
    169     
    170     % Plot the render time if there were no render delay.
    171     x = (renderTime(:,1) - firstTimeStamp)/90;
    172     if flat
    173         slope = x;
    174     end
    175     plot(x, renderTime(:,2) - firstTime - slope - renderTime(:, 3) - renderTime(:, 5), 'b-');
    176 end
    177 
    178 %plot(x, 90*x, 'r-');
    179 
    180 xlabel('RTP timestamp (in ms)');
    181 ylabel('Time (ms)');
    182 legend('Packet arrives', 'Frame complete', 'Decode', 'Decode complete', 'Time to render', 'Only jitter', 'Must decode');
    183 
    184 % subplot(312);
    185 % hold on;
    186 % completeTs = completeTime(:, 1);
    187 % arrivalTs = estimatedArrivalTime(:, 1);
    188 % [c, completeIdx, arrivalIdx] = intersect(completeTs, arrivalTs);
    189 % %plot(completeTs(completeIdx), completeTime(completeIdx, 3) - estimatedArrivalTime(arrivalIdx, 2));
    190 % timeUntilComplete = completeTime(completeIdx, 3) - estimatedArrivalTime(arrivalIdx, 2);
    191 % devFromAvgCompleteTime = timeUntilComplete - mean(timeUntilComplete);
    192 % plot(completeTs(completeIdx) - completeTs(completeIdx(1)), devFromAvgCompleteTime);
    193 % plot(completeTime(:, 1) - completeTime(1, 1), completeTime(:, 4), 'r');
    194 % plot(decodeCompleteTime(:, 1) - decodeCompleteTime(1, 1), decodeCompleteTime(:, 2), 'g');
    195 % plot(decodeCompleteTime(:, 1) - decodeCompleteTime(1, 1), decodeCompleteTime(:, 3), 'k');
    196 % xlabel('RTP timestamp');
    197 % ylabel('Time (ms)');
    198 % legend('Complete time - Estimated arrival time', 'Desired jitter buffer level', 'Actual decode time', 'Max decode time', 0);
    199 
    200 if prod(size(renderTime)) > 0
    201     subplot(212);
    202     hold on;
    203     firstTime = renderTime(1, 1);
    204     targetDelay = max(renderTime(:, 3) + renderTime(:, 4) + renderTime(:, 5), renderTime(:, 6));
    205     plot(renderTime(:, 1) - firstTime, renderTime(:, 3), 'r-');
    206     plot(renderTime(:, 1) - firstTime, renderTime(:, 4), 'b-');
    207     plot(renderTime(:, 1) - firstTime, renderTime(:, 5), 'g-');
    208     plot(renderTime(:, 1) - firstTime, renderTime(:, 6), 'k-');
    209     plot(renderTime(:, 1) - firstTime, targetDelay, 'c-');
    210     xlabel('RTP timestamp');
    211     ylabel('Time (ms)');
    212     legend('Render delay', 'Jitter delay', 'Decode delay', 'Extra delay', 'Min total delay');
    213 end